Tests that try to log in frequently time out on rikku-release |
|||||||||||||
Issue descriptionSeveral Tast tests that require login (ui.ChromeCrashLoggedIn, ui.ChromeLogin) timed out while waiting for cryptohome on rikku-release builds running against DUT chromeos4-row3-rack5-host1: R69-10895.27.0: http://stainless/browse/chromeos-autotest-results/227989883-chromeos-test/ R70-10972.0.0: http://stainless/browse/chromeos-autotest-results/227813290-chromeos-test/ The pattern in the logs appears to be the same in all cases. We time out after waiting about two minutes for the cryptohome dir to be mounted: 2018/08/15 14:58:42 Started test ui.ChromeCrashLoggedIn 2018/08/15 14:58:42 [14:58:41.829] Restarting ui job 2018/08/15 14:58:43 [14:58:42.992] Waiting for org.chromium.SessionManager D-Bus service 2018/08/15 14:58:43 [14:58:43.008] Asking session_manager to enable Chrome testing 2018/08/15 14:58:43 [14:58:43.009] Waiting for Chrome to write its debugging port to /home/chronos/DevToolsActivePort 2018/08/15 14:58:43 [14:58:43.610] Removing cryptohome for testuser@gmail.com 2018/08/15 14:58:43 [14:58:43.654] Finding OOBE DevTools target 2018/08/15 14:58:44 [14:58:43.932] Connecting to Chrome at ws://127.0.0.1:53974/devtools/page/8C78752C523A9154FAC3D627310B46DB 2018/08/15 14:58:44 [14:58:44.027] Waiting for OOBE 2018/08/15 14:58:46 [14:58:46.317] Logging in as user "testuser@gmail.com" 2018/08/15 14:58:46 [14:58:46.402] Waiting for cryptohome /home/user/fec8f6ba0f6c3b178f8adb7e643b6d91187c1db8 ... 2018/08/15 15:00:39 [15:00:39.038] Error at chrome_crash_logged_in.go:27: Chrome login failed: /home/user/fec8f6ba0f6c3b178f8adb7e643b6d91187c1db8 not mounted: context deadline exceeded We log additional info on failure now as discussed in issue 864282 . The DUT doesn't appear to be exhibiting the problem suspected in that issue, though -- both cryptohome and the TPM device itself report that the TPM is owned: 2018/08/15 15:00:39 [15:00:39.007] 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": false, "can_encrypt": false, "can_load_srk": true, "can_load_srk_pubkey": true, "enabled": true, "has_context": true, "has_cryptohome_key": false, "has_key_handle": false, "last_error": 0, "owned": true, "srk_vulnerable_roca": true } } 2018/08/15 15:00:39 [15:00:39.037] /sys/class/misc/tpm0/device/owned contains "1" I see the following in /var/log/messages during the period where the test is waiting: 2018-08-15T14:58:46.426254-07:00 INFO kernel: [ 3378.918334] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0 2018-08-15T14:58:46.562587-07:00 INFO session_manager[20048]: [INFO:server_backed_state_key_generator.cc(126)] Stable device secret missing! 2018-08-15T15:00:38.889212-07:00 INFO kernel: [ 3491.340620] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0 2018-08-15T15:00:38.974224-07:00 INFO kernel: [ 3491.426289] tpm_tis tpm_tis: command 0x21 (size 59) returned code 0x0 2018-08-15T15:00:39.005233-07:00 INFO kernel: [ 3491.456536] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22 2018-08-15T15:00:39.038299-07:00 INFO kernel: [ 3491.489584] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0 2018-08-15T15:00:39.100078-07:00 INFO session_manager[20048]: [INFO:browser_job.cc(167)] Terminating browser process 20066 with signal 15: exiting cleanly 2018-08-15T15:00:39.100099-07:00 INFO session_manager[20048]: [INFO:system_utils_impl.cc(94)] Sending 15 to 20066 as 1000 2018-08-15T15:00:39.295805-07:00 INFO session_manager[20048]: [INFO:session_manager_service.cc(481)] SessionManagerService quitting run loop 2018-08-15T15:00:39.295848-07:00 INFO session_manager[20048]: [INFO:session_manager_service.cc(201)] SessionManagerService exiting Andrey, are those tpm_tis log messages expected or indicative of the problem? Any other guesses? It looks like a bunch of Autotest-based tests failed on the DUT around the same time with similar cryptohome errors, so this is probably something that the Autotest verify/repair code should handle (once we have a way to detect the problem): http://stainless/search?view=matrix&row=test&col=build&first_date=2018-08-14&last_date=2018-08-16&hostname=chromeos4-row3-rack5-host1&status=FAIL&exclude_cts=false&exclude_not_run=false&exclude_non_release=true&exclude_au=true&exclude_acts=true&exclude_retried=true&exclude_non_production=false I'm happy to try to update it to detect this if you can help me figure out the criteria. :-)
,
Aug 17
FTR looking at logs from R70-10972.0.0: http://stainless/browse/chromeos-autotest-results/227813290-chromeos-test/ since excerpts from those logs are provided above. It started at ~14:25: 2018-08-15T14:25:20.444828-07:00 NOTICE autotest[11114]: 14:25:20.435 ERROR| chrome:0192| Timed out logging in, tries=0, error=LoginException('Timed out going through login screen. Cryptohome not mounted. OOBE not dismissed.',) From what I see in chrome logs, chrome didn't attempt to login at all. It clicked through OOBE, updated, restarted, and is just sitting there not logging in: <Start of Chrome process #1 = 8701, logged in https://storage.cloud.google.com/chromeos-autotest-results/227813290-chromeos-test/chromeos4-row3-rack5-host1/tast/sysinfo/var/log/chrome/chrome_20180815-141007> 2018-08-15T14:10:07.254586-07:00 INFO session_manager[8634]: [INFO:browser_job.cc(148)] Running browser /opt/google/chrome/chrome --ppapi-flash-path=/opt/google/chrome/pepper/libpepflashplayer.so --ppapi-flash-version=30.0.0.142 --ui-prioritize-in-gpu-process --use-gl=egl --enable-native-gpu-memory-buffers --gpu-sandbox-failures-fatal=yes --enable-logging --log-level=1 --use-cras --enable-wayland-server --user-data-dir=/home/chronos --system-developer-mode --login-profile=user --aura-legacy-power-button --guest-wallpaper-large=/usr/share/chromeos-assets/wallpaper/guest_large.jpg --guest-wallpaper-small=/usr/share/chromeos-assets/wallpaper/guest_small.jpg --child-wallpaper-large=/usr/share/chromeos-assets/wallpaper/child_large.jpg --child-wallpaper-small=/usr/share/chromeos-assets/wallpaper/child_small.jpg --default-wallpaper-large=/usr/share/chromeos-assets/wallpaper/oem_large.jpg --default-wallpaper-small=/usr/share/chromeos-assets/wallpaper/oem_small.jpg --default-wallpaper-is-oem --enable-consumer-kiosk --enterprise-enrollment-initial-modulus=15 --enterprise-enrollment-modulus-limit=19 --login-manager --enable-net-benchmarking --metrics-recording-only --no-default-browser-check --no-first-run --enable-gpu-benchmarking --deny-permission-prompts --autoplay-policy=no-user-gesture-required --disable-component-extensions-with-background-pages --disable-default-apps --disable-search-geolocation-disclosure --enable-smooth-scrolling --enable-threaded-compositing --remote-debugging-port=0 --start-maximized --ash-disable-system-sounds --oobe-skip-postlogin --disable-logging-redirect --allow-failed-policy-fetch-for-test --disable-gaia-services --testing-channel=NamedTestingInterface:/tmp/.org.chromium.Chromium.rd7UDv/.org.chromium.Chromium.SQdJgG --vmodule=*/assistant/*=1,*chromeos/login/*=1,auto_enrollment_controller=1,*/ui/ozone/*=1,*/ui/display/manager/chromeos/*=1,*night_light*=1,update_engine=1,component_updater_service=1,power_button_observer=2,webui_login_view=2,lock_state_controller=2,webui_screen_locker=2,screen_locker=2,*/chromeos/net/*=2,*/chromeos/login/*=2,chrome_browser_main_posix=2 --show-webui-login <Note that at this point TPM is not owned yet> 2018-08-15T14:10:10.656961-07:00 ERR cryptohomed[717]: TpmIsReady: is not owned. 2018-08-15T14:10:10.656980-07:00 ERR cryptohomed[717]: HasAuthorization: TPM not ready. 2018-08-15T14:10:10.656990-07:00 ERR cryptohomed[717]: Destroy() called with insufficient authorization. <Chrome #1 goes through OOBE, shows update screen, is shut down> [8701:8701:0815/141007.707470:WARNING:install_attributes.cc(101)] Install attributes missing, first sign in ... [8701:8701:0815/141008.121593:VERBOSE1:wizard_controller.cc(326)] Starting OOBE wizard with screen: connect [8701:8701:0815/141008.122001:VERBOSE1:wizard_controller.cc(509)] Showing welcome screen. ... [8701:8701:0815/141010.653879:VERBOSE1:wizard_controller.cc(785)] SkipToLoginForTesting. [8701:8701:0815/141010.654352:VERBOSE1:auto_enrollment_controller.cc(539)] Auto-enrollment disabled: command line (gaia). [8701:8701:0815/141010.654387:VERBOSE1:auto_enrollment_controller.cc(732)] New auto-enrollment state: 5 [8701:8701:0815/141010.656053:VERBOSE1:wizard_controller.cc(1976)] Showing enrollment screen. Forcing interactive enrollment: 0. [8701:8701:0815/141010.656129:VERBOSE1:wizard_controller.cc(1279)] SetCurrentScreenSmooth: oauth-enrollment [8701:8701:0815/141010.656955:VERBOSE1:gaia_screen_handler.cc(774)] HandleCompleteLogin ... [8701:8701:0815/141011.143312:VERBOSE1:signin_screen_handler.cc(1437)] Login WebUI >> loginVisible, src: oobe, webui_visible_: 0 [8701:8701:0815/141011.143559:VERBOSE1:webui_login_view.cc(614)] Login WebUI >> login-prompt-visible [8701:8701:0815/141011.189167:WARNING:enrollment_screen_handler.cc(665)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update ... [8701:8701:0815/141607.966257:VERBOSE1:component_updater_service.cc(321)] CheckForUpdates: automatic updatecheck for components. [8701:8701:0815/141608.238564:VERBOSE1:component_updater_service.cc(412)] Update completed with error 0 [8701:8701:0815/141732.270910:WARNING:enrollment_screen_handler.cc(665)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update [8701:8701:0815/142232.454010:WARNING:enrollment_screen_handler.cc(665)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update <Terminating Chrome #1> 2018-08-15T14:25:19.335129-07:00 INFO session_manager[8634]: [INFO:browser_job.cc(167)] Terminating browser process 8701 with signal 15: exiting cleanly 2018-08-15T14:25:19.335151-07:00 INFO session_manager[8634]: [INFO:system_utils_impl.cc(94)] Sending 15 to 8701 as 1000 ... [8701:8701:0815/142519.487779:VERBOSE1:component_updater_service.cc(108)] CrxUpdateService stopping [8701:8701:0815/142519.488203:WARNING:pref_notifier_impl.cc(23)] Pref observer found at shutdown. ... 2018-08-15T14:25:19.531527-07:00 INFO session_manager[8634]: [INFO:session_manager_service.cc(481)] SessionManagerService quitting run loop 2018-08-15T14:25:19.531969-07:00 INFO session_manager[8634]: [INFO:session_manager_service.cc(201)] SessionManagerService exiting <Start of Chrome process #2 = 11155, logged in https://storage.cloud.google.com/chromeos-autotest-results/227813290-chromeos-test/chromeos4-row3-rack5-host1/tast/sysinfo/var/log/chrome/chrome_20180815-142520> 2018-08-15T14:25:20.401847-07:00 INFO session_manager[11087]: [INFO:browser_job.cc(148)] Running browser /opt/google/chrome/chrome --ppapi-flash-path=/opt/google/chrome/pepper/libpepflashplayer.so --ppapi-flash-version=30.0.0.142 --ui-prioritize-in-gpu-process --use-gl=egl --enable-native-gpu-memory-buffers --gpu-sandbox-failures-fatal=yes --enable-logging --log-level=1 --use-cras --enable-wayland-server --user-data-dir=/home/chronos --system-developer-mode --login-profile=user --aura-legacy-power-button --guest-wallpaper-large=/usr/share/chromeos-assets/wallpaper/guest_large.jpg --guest-wallpaper-small=/usr/share/chromeos-assets/wallpaper/guest_small.jpg --child-wallpaper-large=/usr/share/chromeos-assets/wallpaper/child_large.jpg --child-wallpaper-small=/usr/share/chromeos-assets/wallpaper/child_small.jpg --default-wallpaper-large=/usr/share/chromeos-assets/wallpaper/oem_large.jpg --default-wallpaper-small=/usr/share/chromeos-assets/wallpaper/oem_small.jpg --default-wallpaper-is-oem --enable-consumer-kiosk --enterprise-enrollment-initial-modulus=15 --enterprise-enrollment-modulus-limit=19 --login-manager --vmodule=*/assistant/*=1,*chromeos/login/*=1,auto_enrollment_controller=1,*/ui/ozone/*=1,*/ui/display/manager/chromeos/*=1,*night_light*=1,update_engine=1,component_updater_service=1,power_button_observer=2,webui_login_view=2,lock_state_controller=2,webui_screen_locker=2,screen_locker=2 <We log our timeout already at this point - looks like Chrome restart is already due to the autotest error?> 2018-08-15T14:25:20.444828-07:00 NOTICE autotest[11114]: 14:25:20.435 ERROR| chrome:0192| Timed out logging in, tries=0, error=LoginException('Timed out going through login screen. Cryptohome not mounted. OOBE not dismissed.',) <Chrome #2: we still haven't owned the device by that point, still showing OOBE> [11155:11155:0815/142521.061798:WARNING:install_attributes.cc(101)] Install attributes missing, first sign in ... [11155:11155:0815/142521.512940:VERBOSE1:login_display_host_webui.cc(817)] Login WebUI >> wp animation done [11155:11155:0815/142521.512976:VERBOSE1:login_display_host_webui.cc(992)] Login WebUI >> Init postponed WebUI [11155:11155:0815/142521.512994:VERBOSE1:login_display_host_webui.cc(618)] Login WebUI >> wizard [11155:11155:0815/142521.517380:VERBOSE1:login_display_host_webui.cc(1080)] Login WebUI >> show login wnd on create [11155:11155:0815/142521.531142:VERBOSE1:wizard_controller.cc(326)] Starting OOBE wizard with screen: connect [11155:11155:0815/142521.532293:VERBOSE1:wizard_controller.cc(509)] Showing welcome screen. [11155:11155:0815/142521.532363:VERBOSE1:wizard_controller.cc(1279)] SetCurrentScreenSmooth: connect ... [11155:11155:0815/142524.078242:VERBOSE1:wizard_controller.cc(1976)] Showing enrollment screen. Forcing interactive enrollment: 0. ... [11155:11155:0815/142524.417616:VERBOSE1:signin_screen_handler.cc(1437)] Login WebUI >> loginVisible, src: oobe, webui_visible_: 0 [11155:11155:0815/142524.417904:VERBOSE1:webui_login_view.cc(614)] Login WebUI >> login-prompt-visible [11155:11155:0815/142524.759824:WARNING:enrollment_screen_handler.cc(665)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update ... [11155:11155:0815/143121.317844:VERBOSE1:component_updater_service.cc(321)] CheckForUpdates: automatic updatecheck for components. [11155:11155:0815/143121.589782:VERBOSE1:component_updater_service.cc(412)] Update completed with error 0 etc I don't see any signs of attempted logins from Chrome side. So no wonder cryptohome is not mounted. alemate@, jdufault@, can you please take a look? As a side note, is it normal that we have ~6 minutes each time between showing the OOBE update screen and actually checking for update and the 'Update complete' line? E.g. [11155:11155:0815/142524.759824:WARNING:enrollment_screen_handler.cc(665)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update ... [11155:11155:0815/143121.317844:VERBOSE1:component_updater_service.cc(321)] CheckForUpdates: automatic updatecheck for components. [11155:11155:0815/143121.589782:VERBOSE1:component_updater_service.cc(412)] Update completed with error 0 What's going on in Chrome at this point?
,
Aug 17
Note that the TPM is not owned when Chrome #1 runs. Owning it is initiated (and successfully completed in ~10 seconds) only as a part of Chrome #2 session: <Lots of TPM activity> 2018-08-15T14:25:21.383850-07:00 INFO kernel: [ 1374.600356] tpm_tis tpm_tis: command 0x7c (size 30) returned code 0x0 2018-08-15T14:25:21.433198-07:00 INFO kernel: [ 1374.650313] tpm_tis tpm_tis: command 0x7c (size 30) returned code 0x0 ... 2018-08-15T14:25:23.936209-07:00 INFO kernel: [ 1377.151839] tpm_tis tpm_tis: command 0x10 (size 79) returned code 0x0 2018-08-15T14:25:23.972205-07:00 INFO kernel: [ 1377.187762] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22 <... and we have the TPM owned> 2018-08-15T14:25:23.974812-07:00 ERR cryptohomed[717]: Taking TPM ownership took 2650ms 2018-08-15T14:25:23.975010-07:00 INFO cryptohomed[717]: Configuring TPM, ownership taken: 1. <.. and attestation prepared> 2018-08-15T14:25:24.682283-07:00 INFO cryptohomed[717]: Attestation: Preparing for enrollment... ... 2018-08-15T14:25:31.874451-07:00 INFO cryptohomed[717]: Attestation: Prepared successfully (7192 ms).
,
Aug 17
Later we start Chrome again and again. Still with the same outcome: we show OOBE, sit there, but never attempt to login, and get timeout from autotest. TPM is already owned by this point.
,
Aug 17
And to complete: I don't see any cryptohomed/tpm activity in the logs for those failed test sessions, though cryptohomed is apparently running and responsive. E.g.:
<we start our session>
2018-08-15T14:54:24.136145-07:00 INFO session_manager[16268]: [INFO:browser_job.cc(148)] Running browser /opt/google/chrome/chrome -[...]
...
<this is the only tpm activity - apparently reading SRK pubkey caused by "cryptohome --action=status" from autotest requesting cryptohomed for status>
2018-08-15T14:54:37.947068-07:00 NOTICE ag[16545]: autotest server[stack::__init__|_get_cryptohome_status|run] -> ssh_run(cryptohome --action=status)
2018-08-15T14:54:38.016247-07:00 INFO kernel: [ 3130.598034] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0 --> OIAP=success
2018-08-15T14:54:38.118248-07:00 INFO kernel: [ 3130.700681] tpm_tis tpm_tis: command 0x21 (size 59) returned code 0x0 --> GetPubKey=success
2018-08-15T14:54:38.149227-07:00 INFO kernel: [ 3130.730910] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22 --> FlushSpecific=unknown_handle
...
<and timeout & close the session>
2018-08-15T14:55:46.130090-07:00 INFO session_manager[16268]: [INFO:browser_job.cc(167)] Terminating browser process 16281 with signal 15: exiting cleanly
2018-08-15T14:55:46.130112-07:00 INFO session_manager[16268]: [INFO:system_utils_impl.cc(94)] Sending 15 to 16281 as 1000
...
2018-08-15T14:55:47.296054-07:00 NOTICE autotest[17171]: 14:55:47.287 ERROR| chrome:0192| Timed out logging in, tries=2, error=LoginException("Timed out going through login screen. Cryptohome not mounted. Browser didn't launch. ",)
,
Aug 17
The Autotest logs quoted in #2 are from an earlier run of a different test. Autotest likes to collect ancient logs. :-/
There are a bunch of timeouts in login-related tests (both Autotest tests and Tast tests) on this DUT; see the Stainless link in the original report.
It seems like something is consistently broken on chromeos4-row3-rack5-host1.cros that prevents login from working. Whatever it is, it persists across reimages. The device currently has 10976.0.0 and is still broken right now when I try to run the ui.ChromeLogin Tast test.
Here's some info collected just now:
# cryptohome --action=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": false,
"can_encrypt": false,
"can_load_srk": true,
"can_load_srk_pubkey": true,
"enabled": true,
"has_context": true,
"has_cryptohome_key": false,
"has_key_handle": false,
"last_error": 0,
"owned": true,
"srk_vulnerable_roca": true
}
}
# cat /sys/class/misc/tpm0/device/owned
1
Are there things besides the TPM that could be persistently breaking login across reimages in this manner? Can you think of anything else that would help debug?
,
Aug 17
Evidence that suggesting that this is rikku-related: I see a similar timeout when running ui.ChromeLogin on chromeos4-row3-rack4-host21 (rikku-release/R70-10974.0.0). Oddly, the same test ran successfully on chromeos4-row3-rack5-host16 (rikku-release/R70-10975.0.0).
,
Aug 17
,
Aug 20
,
Aug 20
It seems like the device starts going through enrollment, but I'm not sure why. auto-enrollment state 5 maps to AUTO_ENROLLMENT_STATE_NO_ENROLLMENT, so I'm surprised that oauth-enrollment screen is being shown.
michaelpg@, could this be related to demo mode?
[20836:20836:0815/150046.485068:VERBOSE1:wizard_controller.cc(785)] SkipToLoginForTesting.
[20836:20836:0815/150046.486513:VERBOSE1:auto_enrollment_controller.cc(539)] Auto-enrollment disabled: command line (gaia).
[20836:20836:0815/150046.486555:VERBOSE1:auto_enrollment_controller.cc(732)] New auto-enrollment state: 5
[20836:20836:0815/150046.486630:VERBOSE1:wizard_controller.cc(1976)] Showing enrollment screen. Forcing interactive enrollment: 0.
[20836:20836:0815/150046.486681:VERBOSE1:wizard_controller.cc(1279)] SetCurrentScreenSmooth: oauth-enrollment
[20836:20836:0815/150046.487884:VERBOSE1:gaia_screen_handler.cc(774)] HandleCompleteLogin
[20836:20836:0815/150046.522994:ERROR:CONSOLE(10473)] "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 (10473)
[20836:20836:0815/150046.523054:ERROR:CONSOLE(416)] "Uncaught TypeError: Cannot read property 'showStep' of null", source: chrome://oobe/oobe.js (416)
,
Aug 20
We don't have autotests for demo mode yet but it's possible some of our changes in places like WizardController to support demo mode could have introduced a regression. Aga, could you take a look?
,
Aug 20
I will check if that is caused by demo mode.
,
Aug 20
> I will check if that is caused by demo mode. Last I knew, demo mode isn't allowed to run on test images. If demo mode _is_ actually running with a test image, that's likely a bug all on its own, whether or not it also causes this problem.
,
Aug 20
Sorry I was not precise. New demo mode itself is guarded by the flag and it is unlikely that device with test image is entering demo mode. But I made changes in OOBE flow and also added tests for demo mode. I will check if it introduced any bug that could cause this test failures (bug in the flow or insufficient mocking in tests).
,
Aug 20
Aga, since these are autotest/tast failures, they wouldn't be related to our browser tests or mocks. I think the question is whether the changes and refactoring we landed for demo mode are somehow affecting existing autotests/tast tests. (We don't have any autotests/tast tests for demo mode yet.)
,
Oct 5
,
Oct 5
Issue 890110 contains additional failures on rikku-release (specifically, on chromeos4-row3-rack5-host4). Aga, were you able to investigate this?
,
Oct 5
Demo mode is not showing oauth-enrollment screen, so it did not seem related. Let me look at the newest failures.
,
Oct 5
Rikku is a chromebox. Are we having different Chromebox models in the lab?
,
Oct 5
I compared logs from successful and failed runs. The failure always happens when showing wizard controller is postponed. Postponing is probably due to web UI being not ready, but not 100% sure about that. (Why it happens only on rikku?) After postponing different code paths are executed and wizard controller is initialized with welcome screen. Without postponing wizard controller initialization is skipped. Successful run: [10812:10812:0904/230900.882890:VERBOSE1:chrome_session_manager.cc(224)] Starting Chrome with login/oobe screen. [10812:10812:0904/230900.882923:VERBOSE1:login_display_host_webui.cc(1151)] Showing OOBE screen: unknown [10812:10812:0904/230900.890037:VERBOSE1:login_display_host_webui.cc(1226)] Current locale: en-US [10812:10812:0904/230900.890110:VERBOSE1:input_events_blocker.cc(19)] InputEventsBlocker 0x2863664daf90 created. [10812:10812:0904/230900.920453:ERROR:login_display_host_mojo.cc(156)] Not implemented reached in virtual void chromeos::LoginDisplayHostMojo::SetStatusAreaVisible(bool) [10812:10812:0904/230900.920524:VERBOSE1:input_events_blocker.cc(28)] InputEventsBlocker 0x2863664daf90 destroyed. [10812:10812:0904/230901.076357:ERROR:login_display_host_mojo.cc(224)] Not implemented reached in virtual void chromeos::LoginDisplayHostMojo::OnPreferencesChanged() ... [10812:10812:0904/230901.089379:VERBOSE1:signin_screen_handler.cc(595)] OnNetworkReady() call. [10812:10812:0904/230901.343256:VERBOSE1:login_display_mojo.cc(63)] Emitting login-prompt-visible [10812:10812:0904/230901.390518:WARNING:CONSOLE(0)] "HTML Imports is deprecated and will be removed in M73, around March 2019. Please use ES modules instead. See https://www.chromestatus.com/features/5144752345317376 for more details.", source: (0) [10812:10812:0904/230901.576057:WARNING:CONSOLE(442)] "document.registerElement is deprecated and will be removed in M73, around March 2019. Please use window.customElements.define instead. See https://www.chromestatus.com/features/4642138092470272 for more details.", source: chrome://resources/polymer/v1_0/polymer/polymer-micro-extracted.js (442) [10812:10950:0904/230901.577758:INFO:nss_cert_database_chromeos.cc(122)] UserCertLogging: Invoked with log_reason=ListCerts, system_slot_present=1 [10812:10939:0904/230901.577705:INFO:nss_cert_database_chromeos.cc(122)] UserCertLogging: Invoked with log_reason=SystemTokenInitiallyLoaded, system_slot_present=1 [10812:10812:0904/230902.526860:WARNING:CONSOLE(2083)] "Element.createShadowRoot is deprecated and will be removed in M73, around March 2019. Please use Element.attachShadow instead. See https://www.chromestatus.com/features/4507242028072960 for more details.", source: chrome://resources/polymer/v1_0/polymer/polymer-mini-extracted.js (2083) [10812:10812:0904/230903.478071:VERBOSE1:gaia_screen_handler.cc(1171)] LoadAuthExtension, force: 1, offline: 0 [10812:10812:0904/230903.498386:INFO:signin_screen_handler.cc(1483)] Login WebUI >> active: 1, source: gaia-signin [10812:10812:0904/230903.560772:VERBOSE1:signin_screen_handler.cc(1437)] Login WebUI >> loginVisible, src: oobe, webui_visible_: 0 [10812:10812:0904/230903.619744:VERBOSE1:gaia_screen_handler.cc(621)] Auth extension finished loading [10812:10812:0904/230903.619842:VERBOSE1:gaia_screen_handler.cc(780)] HandleCompleteLogin [10812:10812:0904/230903.620004:VERBOSE1:signin_screen_handler.cc(1437)] Login WebUI >> loginVisible, src: gaia-loading, webui_visible_: 1 [10812:10812:0904/230903.622754:VERBOSE1:existing_user_controller.cc(574)] Setting flow from PerformLogin [10812:10812:0904/230903.622807:VERBOSE1:user_flow.cc(21)] Flow 0x28636598e6a0 got host 0x2863656df540 [10812:10812:0904/230903.623126:VERBOSE1:login_performer.cc(287)] Online login completion started. [10812:10812:0904/230903.623452:VERBOSE1:cryptohome_authenticator.cc(811)] Resolved state to: 0 [10812:10812:0904/230903.628501:ERROR:device_event_log_impl.cc(159)] [23:09:03.628] Login: cryptohome_util.cc:131 GetKeyDataEx failed with no GetKeyDataReply extension in reply. [10812:10812:0904/230903.632104:ERROR:device_event_log_impl.cc(159)] [23:09:03.632] Login: cryptohome_authenticator.cc:147 MountEx failed. Error: 32 [10812:10812:0904/230903.632154:ERROR:device_event_log_impl.cc(159)] [23:09:03.632] Login: cryptohome_authenticator.cc:971 Cryptohome failure: state(AuthState)=1, code(cryptohome::MountError)=32 [10812:10812:0904/230903.632178:VERBOSE1:cryptohome_authenticator.cc(811)] Resolved state to: 6 [10812:10812:0904/230903.661926:ERROR:CONSOLE(217)] "Unexpected condition on chrome://oobe/gaia-signin: Could not find value for languageList", source: chrome://resources/js/load_time_data.js (217) [10812:10812:0904/230905.427793:VERBOSE1:cryptohome_authenticator.cc(811)] Resolved state to: 13 [10812:10812:0904/230905.427868:VERBOSE1:cryptohome_authenticator.cc(701)] Login success [10812:10812:0904/230905.428261:VERBOSE1:login_performer.cc(87)] LoginSuccess hash: 6325860f5fcf7d5ff9479d6eb7f74368aa04efe7 Failed run: [887:887:0904/151223.798528:VERBOSE1:chrome_session_manager.cc(224)] Starting Chrome with login/oobe screen. [887:887:0904/151223.798595:VERBOSE1:login_display_host_webui.cc(1151)] Showing OOBE screen: unknown [887:887:0904/151223.801937:VERBOSE1:login_display_host_webui.cc(431)] Login WebUI >> zero_delay: 0 wait_for_wp_load_: 1 init_webui_hidden_: 0 [887:887:0904/151223.801994:VERBOSE1:login_display_host_webui.cc(537)] Login WebUI >> wizard postponed ... [887:887:0904/151224.934064:VERBOSE1:login_display_host_webui.cc(736)] Login WebUI >> wp animation done [887:887:0904/151224.934109:VERBOSE1:login_display_host_webui.cc(913)] Login WebUI >> Init postponed WebUI [887:887:0904/151224.934129:VERBOSE1:login_display_host_webui.cc(540)] Login WebUI >> wizard [887:887:0904/151224.941856:VERBOSE1:login_display_host_webui.cc(998)] Login WebUI >> show login wnd on create [887:887:0904/151224.971297:VERBOSE1:wizard_controller.cc(338)] Starting OOBE wizard with screen: connect [887:887:0904/151224.971427:VERBOSE1:wizard_controller.cc(535)] Showing welcome screen. [887:887:0904/151224.971494:VERBOSE1:wizard_controller.cc(1333)] SetCurrentScreenSmooth: connect
,
Oct 5
Reassigning to Jacob, as he should be most familiar with that.
,
Oct 6
Jacob, when do you think you'll be able to investigate these failures?
,
Oct 9
,
Oct 9
Probably more instances of this (on chromeos4-row3-rack5-host4): http://stainless/browse/chromeos-autotest-results/246689328-chromeos-test/
,
Oct 9
Filed http://b/117491190 to repair chromeos4-row3-rack5-host4.
,
Oct 12
Per the Buganizer bug, it sounds like these devices might be stuck in CfM enrollment: --- "The device was defaulting to CFM enrollment on boot, i.e. it wanted to "setup meeting room hardware". Following the guidance of a previous bug with the same issue (http://b/67336749), I ran "vpd -l -i RW_VPD | grep 'oem_device_requisition'". It yielded "oem_device_requisition"="remora" so I removed it via "vpd -i RW_VPD -d "oem_device_requisition"" and then pressed CTRL + ALT + H and selected "no" to return to normal login screen. After rebooting/powerwashing, the meeting room hardware setup screen does not come back." --- Is this something that we should be detecting and repairing?
,
Oct 12
If I understand this right CfM tests leave the device enrolled causing problems for anybody after? In principle a reset job could be added like the change below, but I wouldn't know how to do the keyboard actions: https://chromium-review.googlesource.com/c/chromiumos/third_party/autotest/+/1262395/4/server/hosts/cros_repair.py Notice reset/repair is super expensive, so it really is a last resort.
,
Oct 23
I haven't seen this happening recently, so I'm going to close it for now. I'm guessing that the enrolled devices have left the pool. |
|||||||||||||
►
Sign in to add a comment |
|||||||||||||
Comment 1 by apronin@chromium.org
, Aug 17