Chrome login logs are indecipherable |
|||
Issue descriptionIn the run at http://stainless/browse/chromeos-autotest-results/240484343-chromeos-test/, the ui.ChromeLogin test failed: ... 2018/09/21 17:33:07 [17:33:07.075] Waiting for OOBE 2018/09/21 17:33:10 [17:33:09.693] Logging in as user "testuser@gmail.com" 2018/09/21 17:33:10 [17:33:09.803] Waiting for cryptohome /home/user/2c20a44575e20aa253ae1490ad4e39a524440b5f ... 2018/09/21 17:35:02 [17:35:01.887] Error at chrome_crash_logged_in.go:24: Chrome login failed: /home/user/2c20a44575e20aa253ae1490ad4e39a524440b5f not mounted: context deadline exceeded (last error: doesn't exist) I see the following in chrome_20180921-173305 from that time period: ... [3851:3851:0921/173306.917825:VERBOSE1:login_display_host_webui.cc(735)] Login WebUI >> wp animation done [3851:3851:0921/173306.917864:VERBOSE1:login_display_host_webui.cc(912)] Login WebUI >> Init postponed WebUI [3851:3851:0921/173306.917901:VERBOSE1:login_display_host_webui.cc(539)] Login WebUI >> wizard [3851:3851:0921/173306.920138:VERBOSE1:login_display_host_webui.cc(998)] Login WebUI >> show login wnd on create [3851:3851:0921/173306.955535:VERBOSE1:wizard_controller.cc(352)] Starting OOBE wizard with screen: connect [3851:3851:0921/173306.955932:VERBOSE1:wizard_controller.cc(549)] Showing welcome screen. [3851:3851:0921/173306.961004:VERBOSE1:wizard_controller.cc(1365)] SetCurrentScreenSmooth: connect [3851:3851:0921/173307.219975: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) [3851:3851:0921/173307.456179: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) [3851:3851:0921/173308.136554: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) [3851:3851:0921/173308.178255:WARNING:CONSOLE(2651)] "Could not find style data in module named", source: chrome://resources/polymer/v1_0/polymer/polymer-extracted.js (2651) [3851:3851:0921/173309.789222:VERBOSE1:wizard_controller.cc(842)] SkipToLoginForTesting. [3851:3851:0921/173309.789801:VERBOSE1:auto_enrollment_controller.cc(539)] Auto-enrollment disabled: command line (gaia). [3851:3851:0921/173309.789833:VERBOSE1:auto_enrollment_controller.cc(732)] New auto-enrollment state: 5 [3851:3851:0921/173309.791293:VERBOSE1:wizard_controller.cc(2085)] Showing enrollment screen. Forcing interactive enrollment: 0. [3851:3851:0921/173309.791358:VERBOSE1:wizard_controller.cc(1365)] SetCurrentScreenSmooth: oauth-enrollment [3851:3851:0921/173309.791801:VERBOSE1:gaia_screen_handler.cc(780)] HandleCompleteLogin [3851:3851:0921/173309.898119:WARNING:CONSOLE(288)] "<webview>: The load has aborted with error -3: ERR_ABORTED.", source: extensions::webViewEvents (288) [3851:3851:0921/173309.903049:ERROR:CONSOLE(10506)] "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 (10506) [3851:3851:0921/173309.903191:ERROR:CONSOLE(416)] "Uncaught TypeError: Cannot read property 'showStep' of null", source: chrome://oobe/oobe.js (416) [3851:3851:0921/173309.909204:VERBOSE1:signin_screen_handler.cc(1426)] Login WebUI >> loginVisible, src: oobe, webui_visible_: 0 [3851:3851:0921/173309.910060:VERBOSE1:webui_login_view.cc(608)] Login WebUI >> login-prompt-visible [3851:3851:0921/173310.086780:WARNING:CONSOLE(2651)] "Could not find style data in module named", source: chrome://resources/polymer/v1_0/polymer/polymer-extracted.js (2651) [3851:3851:0921/173310.267887:WARNING:CONSOLE(288)] "<webview>: The load has aborted with error -3: ERR_ABORTED.", source: extensions::webViewEvents (288) [3851:3851:0921/173310.323718:WARNING:enrollment_screen_handler.cc(670)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update [3851:3851:0921/173312.953093:WARNING:enrollment_screen_handler.cc(670)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update [3851:3851:0921/173313.713125:WARNING:CONSOLE(17471)] "Unrecognized message from GAIA: showConfirmCancel", source: chrome://oobe/oobe.js (17471) [3851:3851:0921/173334.202996:WARNING:enrollment_screen_handler.cc(670)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update [3851:3851:0921/173359.901140:WARNING:enrollment_screen_handler.cc(670)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update [3851:3851:0921/173424.581194:WARNING:enrollment_screen_handler.cc(670)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update [3851:3851:0921/173502.123651:VERBOSE1:component_updater_service.cc(107)] CrxUpdateService stopping [3851:3851:0921/173502.123958:WARNING:pref_notifier_impl.cc(23)] Pref observer found at shutdown. [3851:3851:0921/173502.123989:WARNING:pref_notifier_impl.cc(23)] Pref observer found at shutdown. EOF The log is full of warning messages and even errors about incorrect JS code, but there's nothing that unambiguously tells me whether we encountered a fatal error during Chrome's part of the login process or not. Please fix logging: a) Remove warnings about not-fatal issues. b) Make Chrome log unambiguous messages about the result of the process like: LOG(INFO) << "Chrome login complete; asking cryptohome to mount user dir"; or LOG(ERROR) << "Chrome login failed in WebUI"; People trying to debug test failures need to be able to tell whether problems are likely to be in Chrome or cryptohomed, at the very least.
,
Sep 24
also the "showConfirmCancel" issue, which shows up in logs for tons of other bugs
,
Sep 24
I think VERBOSE1 is a good idea for */chromeos/login/*. I'd file a separate bug (assign to jdufault@) to rationalize the logging there as well.
,
Sep 24
#1: This is the default logging that every device uses. (--disable-logging-redirect is set to divert logging from the cryptohome, but that's likely irrelevant here.)
session_manager's chrome_setup.cc contains the following:
builder->AddVmodulePattern("screen_locker=2");
builder->AddVmodulePattern("webui_screen_locker=2");
builder->AddVmodulePattern("lock_state_controller=2");
builder->AddVmodulePattern("webui_login_view=2");
...
builder->AddVmodulePattern("auto_enrollment_controller=1");
...
builder->AddVmodulePattern("*chromeos/login/*=1");
If some of those patterns are no longer needed, please remove them. I'm happy to LGTM session_manager and Chrome changes that remove logging.
I'll let Jacob decide if it makes sense to split this up into separate bugs. The most important part is adding or modifying messages to make it clear whether Chrome's part of the login process succeeded or failed.
,
Sep 24
+1 to cleanup here. Dan didn't copy/paste it, but those lines in chrome_setup.cc have references to a variety of old-ish bugs: // There has been a steady supply of bug reports about screen locking. These // messages are useful for determining what happened within feedback reports. // See crbug.com/452599. builder->AddVmodulePattern("screen_locker=2"); builder->AddVmodulePattern("webui_screen_locker=2"); builder->AddVmodulePattern("lock_state_controller=2"); builder->AddVmodulePattern("webui_login_view=2"); builder->AddVmodulePattern("power_button_observer=2"); // TODO(xiaochu): Remove after https://crbug.com/851151 is fixed. builder->AddVmodulePattern("component_updater_service=1"); builder->AddVmodulePattern("update_engine=1"); // TODO(afakhry): Remove after Night Light has launched: // https://crbug.com/841846 builder->AddVmodulePattern("*night_light*=1"); // Turn on logging about external displays being connected and disconnected. // Different behavior is seen from different displays and these messages are // used to determine what happened within feedback reports. builder->AddVmodulePattern("*/ui/display/manager/chromeos/*=1"); // Turn on basic logging for Ozone platform implementations. builder->AddVmodulePattern("*/ui/ozone/*=1"); // Needed for investigating auto-enrollment issues. // TODO(tnagel): Remove after switching to device_event_log: // http://crbug.com/636184 builder->AddVmodulePattern("auto_enrollment_controller=1"); // TODO(jdufault): Remove after Views-based login has launched: // https://crbug.com/784495 builder->AddVmodulePattern("*chromeos/login/*=1"); // TODO(xiaohuic): Remove after native assistant has launched: // http://crbug.com/814097 builder->AddVmodulePattern("*/assistant/*=1"); // TODO(https://crbug.com/844537): Needed for investigating issues with // disappearing device-wide certificates. builder->AddVmodulePattern("nss_cert_database_chromeos=1"); if (builder->UseFlagIsSet("cheets")) builder->AddVmodulePattern("*arc/*=1");
,
Sep 24
We're planning on doing some cleanup work and I think this falls nicely into that bucket.
,
Sep 28
For my own edification, I've started http://doc/1GJKIMaUx01GVu2hZswekxgfd5OE4MVc08sjig5z-rbs to try to document what the various errors from Chrome (and also session_manager and cryptohomed) mean.
,
Sep 28
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/a4285863d8ddb8e12eaad92e579267ea81910250 commit a4285863d8ddb8e12eaad92e579267ea81910250 Author: Daniel Erat <derat@chromium.org> Date: Fri Sep 28 18:20:51 2018 chromeos: Stringify status codes in login messages. In an attempt to make login failures easier to debug, update several messages describing progress and errors to include string descriptions of numeric codes: Policy validation failed: 2 Session manager operation failed: 5 Failed to retrieve cros policies. Reason: 5 Resolved state to: 13 Bug: 888520 Change-Id: I8c331c6af7f68dd2e0aa7cdfc98336f4af27f9c2 Reviewed-on: https://chromium-review.googlesource.com/1249730 Reviewed-by: Xiyuan Xia <xiyuan@chromium.org> Reviewed-by: Sergey Poromov <poromov@chromium.org> Commit-Queue: Dan Erat <derat@chromium.org> Cr-Commit-Position: refs/heads/master@{#595160} [modify] https://crrev.com/a4285863d8ddb8e12eaad92e579267ea81910250/chrome/browser/chromeos/settings/device_settings_provider.cc [modify] https://crrev.com/a4285863d8ddb8e12eaad92e579267ea81910250/chrome/browser/chromeos/settings/device_settings_service.cc [modify] https://crrev.com/a4285863d8ddb8e12eaad92e579267ea81910250/chrome/browser/chromeos/settings/device_settings_service.h [modify] https://crrev.com/a4285863d8ddb8e12eaad92e579267ea81910250/chrome/browser/chromeos/settings/session_manager_operation.cc [modify] https://crrev.com/a4285863d8ddb8e12eaad92e579267ea81910250/chromeos/login/auth/cryptohome_authenticator.cc [modify] https://crrev.com/a4285863d8ddb8e12eaad92e579267ea81910250/components/policy/core/common/cloud/cloud_policy_validator.cc [modify] https://crrev.com/a4285863d8ddb8e12eaad92e579267ea81910250/components/policy/core/common/cloud/cloud_policy_validator.h
,
Dec 14
|
|||
►
Sign in to add a comment |
|||
Comment 1 by michae...@chromium.org
, Sep 24You do seem to have verbose logging enabled. Some of the console warnings are irrelevant and occur in other WebUI (deprecation warnings). I think it's worth filing bugs about specific issues: * unnecessary LOG(WARNING)s in enrollment_screen_handler.cc * OOBE JS errors ("TypeError: Cannot read property 'showStep' of null") * OOBE webview errors ("<webview>: The load has aborted with error -3: ERR_ABORTED.") * OOBE Polymer style module warnings ("Could not find style data in module named:")