Issue metadata
Sign in to add a comment
|
Chrome aborts during test login with "Calling GetLastUsedProfile() before profile initialization is completed." |
||||||||||||||||||||||
Issue descriptionI've been running a few Tast (go/tast) VM tests on the betty-release builder, and I've noticed frequent failures due to Chrome crashes during login. In http://uberchromegw/i/chromeos/builders/betty-release/builds/758, the ui.MashLogin test failed: ... 2017/12/01 05:54:44 [05:54:43.614] Waiting for OOBE 2017/12/01 05:54:45 [05:54:45.109] Logging in as user "testuser@gmail.com" 2017/12/01 05:54:45 [05:54:45.178] Waiting for cryptohome /home/user/88b73df71f439a6cb8fc3b8b75db1457e077652c 2017/12/01 05:54:50 [05:54:49.935] Waiting for OOBE to be dismissed 2017/12/01 05:55:42 [05:55:42.415] Error at test.go:79: Test timed out: context deadline exceeded ... 2017/12/01 05:55:42 [05:55:42.418] Error at mash_login.go:24: Chrome probably crashed on startup: OOBE not dismissed: context deadline exceeded syslog confirms that Chrome crashed: 2017-12-01T13:54:49.950945+00:00 INFO session_manager[5209]: [INFO:session_manager_impl.cc(632)] Starting user session 2017-12-01T13:54:49.955462+00:00 WARNING chapsd[613]: No TPM is available. Loading a software-only token. 2017-12-01T13:54:49.958449+00:00 INFO chapsd[613]: Slot 1 ready for token at /home/root/88b73df71f439a6cb8fc3b8b75db1457e077652c/chaps 2017-12-01T13:54:49.959756+00:00 INFO cryptohomed[849]: A Pkcs11_Init event got finished. 2017-12-01T13:54:49.959845+00:00 INFO cryptohomed[849]: PKCS#11 initialization succeeded. 2017-12-01T13:54:49.970861+00:00 INFO crash_reporter[5498]: libminijail[5498]: mount /dev/log -> /dev/log type '' 2017-12-01T13:54:49.980550+00:00 WARNING crash_reporter[5498]: [user] Received crash notification for chrome[5238] sig 6, user 1000 (ignoring call by kernel - chrome crash; waiting for chrome to call us directly) 2017-12-01T13:54:49.980771+00:00 WARNING crash_reporter[5498]: [ARC] Received crash notification for chrome[5238] sig 6, user 1000 (ignoring - crash origin is not ARC) Here's the end of the Chrome log: ... [5238:5238:1201/075445.108044:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.CryptohomeInterface.NeedsDircryptoMigration: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.GLib.ErrorError: Method invoked for NeedsDircryptoMigration returned FALSE but did not set error [5238:5238:1201/075445.108106:ERROR:user_selection_screen.cc(283)] Failed to call cryptohome NeedsDircryptoMigration. [5238:5238:1201/075445.163267:VERBOSE1:gaia_screen_handler.cc(685)] HandleCompleteLogin [5238:5238:1201/075445.165730:VERBOSE1:existing_user_controller.cc(545)] Setting flow from PerformLogin [5238:5238:1201/075445.165784:VERBOSE1:user_flow.cc(21)] Flow 0x239a2d79afc0 got host 0x239a2d406000 [5238:5238:1201/075445.165946:VERBOSE1:login_performer.cc(288)] Online login completion started. [5238:5238:1201/075445.166201:VERBOSE1:cryptohome_authenticator.cc(774)] Resolved state to: 0 [5238:5238:1201/075445.177389:ERROR:device_event_log_impl.cc(156)] [07:54:45.177] Login: homedir_methods.cc:283 HomedirMethods MountEx error (CryptohomeErrorCode): 1 [5238:5238:1201/075445.177478:ERROR:device_event_log_impl.cc(156)] [07:54:45.177] Login: cryptohome_authenticator.cc:931 Cryptohome failure: state(AuthState)=1, code(cryptohome::MountError)=32 [5238:5238:1201/075445.177524:VERBOSE1:cryptohome_authenticator.cc(774)] Resolved state to: 6 [5238:5238:1201/075445.414146:INFO:signin_screen_handler.cc(1286)] Login WebUI >> AccountPickerReady [5238:5238:1201/075445.414372:VERBOSE1:gaia_screen_handler.cc(270)] MaybePreloadAuthExtension [5238:5238:1201/075445.414568:VERBOSE1:gaia_screen_handler.cc(954)] LoadAuthExtension, force: 1, offline: 0 [5238:5238:1201/075445.414771:VERBOSE1:signin_screen_handler.cc(1340)] Login WebUI >> loginVisible, src: account-picker, webui_visible_: 1 [5238:5238:1201/075445.417270:ERROR:devicetype.cc(31)] Unknown device type "OTHER" [5238:5238:1201/075445.432058:VERBOSE1:gaia_screen_handler.cc(512)] OnPortalDetectionCompleted Online [5238:5238:1201/075445.490526:VERBOSE1:gaia_screen_handler.cc(534)] Auth extension finished loading [5238:5238:1201/075445.727452:WARNING:server_backed_state_keys_broker.cc(76)] Failed to obtain server-backed state keys. [5238:5238:1201/075446.546311:VERBOSE1:gaia_screen_handler.cc(708)] Gaia is loaded [5238:5238:1201/075446.546597:VERBOSE1:signin_screen_handler.cc(1340)] Login WebUI >> loginVisible, src: gaia-signin, webui_visible_: 1 [1:10:1201/075447.376824:ERROR:layer_tree_host_impl.cc(2521)] Forcing zero-copy tile initialization as worker context is missing [5238:5238:1201/075447.554194:ERROR:remote_text_input_client.cc(135)] Not implemented reached in virtual void RemoteTextInputClient::OnInputMethodChanged() [5238:5238:1201/075447.554254:ERROR:remote_text_input_client.cc(92)] Not implemented reached in virtual bool RemoteTextInputClient::HasCompositionText() const [5238:5238:1201/075447.554327:ERROR:remote_text_input_client.cc(98)] Not implemented reached in virtual bool RemoteTextInputClient::GetTextRange(gfx::Range *) const [5238:5238:1201/075447.563631:WARNING:CONSOLE(18339)] "Unrecognized message from GAIA: showConfirmCancel", source: chrome://oobe/login.js (18339) [5238:5238:1201/075449.933493:VERBOSE1:cryptohome_authenticator.cc(774)] Resolved state to: 13 [5238:5238:1201/075449.933698:VERBOSE1:cryptohome_authenticator.cc(664)] Login success [5238:5238:1201/075449.933907:VERBOSE1:login_performer.cc(87)] LoginSuccess hash: 88b73df71f439a6cb8fc3b8b75db1457e077652c [5238:5238:1201/075449.933945:VERBOSE1:user_session_manager.cc(497)] Starting user session. [5238:5238:1201/075449.947434:FATAL:profile_manager.cc(646)] Calling GetLastUsedProfile() before profile initialization is completed. So Chrome ultimately aborts with "Calling GetLastUsedProfile() before profile initialization is completed.", which was added by https://codereview.chromium.org/2942043002 for issue 718734. There are tons of cryptohomed errors in the messages file: 2017-12-01T13:54:45.107560+00:00 ERR cryptohomed[849]: Unknown user. 2017-12-01T13:54:45.185343+00:00 WARNING cryptohomed[849]: TSS: Failed unix connect: /var/run/tcsd.socket - No such file or directory 2017-12-01T13:54:45.185468+00:00 WARNING cryptohomed[849]: TSS: Got a list of valid IPs 2017-12-01T13:54:45.186074+00:00 WARNING cryptohomed[849]: TSS: Could not connect to machine: localhost 2017-12-01T13:54:45.186128+00:00 ERR cryptohomed[849]: TSS: Could not connect to any machine in the list. 2017-12-01T13:54:45.186145+00:00 ERR cryptohomed[849]: TSS: Failed to send packet 2017-12-01T13:54:45.286451+00:00 WARNING cryptohomed[849]: TSS: Failed unix connect: /var/run/tcsd.socket - No such file or directory 2017-12-01T13:54:45.286592+00:00 WARNING cryptohomed[849]: TSS: Got a list of valid IPs 2017-12-01T13:54:45.287233+00:00 WARNING cryptohomed[849]: TSS: Could not connect to machine: localhost 2017-12-01T13:54:45.287295+00:00 ERR cryptohomed[849]: TSS: Could not connect to any machine in the list. 2017-12-01T13:54:45.287311+00:00 ERR cryptohomed[849]: TSS: Failed to send packet 2017-12-01T13:54:45.387567+00:00 WARNING cryptohomed[849]: TSS: Failed unix connect: /var/run/tcsd.socket - No such file or directory 2017-12-01T13:54:45.387717+00:00 WARNING cryptohomed[849]: TSS: Got a list of valid IPs 2017-12-01T13:54:45.388440+00:00 WARNING cryptohomed[849]: TSS: Could not connect to machine: localhost 2017-12-01T13:54:45.388504+00:00 ERR cryptohomed[849]: TSS: Could not connect to any machine in the list. 2017-12-01T13:54:45.388521+00:00 ERR cryptohomed[849]: TSS: Failed to send packet ... I think that these may be expected, though (since there's no TPM in the VM). Xiyuan, do you have any ideas about what's going on here? There are a bunch of calls to GetLastUsedProfile, and I'm not sure which one is triggering this check. It's likely that this test is logging in more quickly than Telemetry does in Autotest-based tests. Any chance that it's hitting a race as a result?
,
Dec 5 2017
I unfortunately don't have a symbolized stack trace for this, or even a minidump file. :-( I filed issue 770562 to track adding crash symbolization to Tast. Do you know if we currently get symbolized stack traces for Chrome crashes on VM builders during Autotest-based tests?
,
Dec 5 2017
I am not 100% sure but I think we collect minidumps in VM tests too. Can you "touch /mnt/stateful_partition/etc/enable_chromium_coredumps" in the VM, run the test to trigger the crash and see if that leaves anything in "/var/coredumps" in the VM afterwards?
,
Dec 5 2017
Adding Alex in case this is related to a profile-related crash he's been investigating.
,
Dec 5 2017
Unfortunately I haven't been able to reproduce the abort when I run the test in a loop on a betty VM running on my workstation, even after ~500 runs so far. :-(
,
Dec 6 2017
Hmm. I finally managed to get a timeout after 875 runs: 2017/12/05 15:14:59 Logging in as user "testuser@gmail.com" 2017/12/05 15:14:59 Waiting for cryptohome /home/user/30e85910b346de99f40283c9f179fc89e8f9651f 2017/12/05 15:15:04 Waiting for OOBE to be dismissed 2017/12/05 15:15:55 Error: [/build/betty/usr/lib/gopath/src/chromiumos/tast/common/testing/test.go:79] Test timed out: context deadline exceeded ... 2017/12/05 15:15:55 Error: [/build/betty/tmp/portage/chromeos-base/tast-local-tests-0.0.1-r29/work/tast-local-tests-0.0.1/src/chromiumos/tast/local/tests/ui/mash_login.go:24] Chrome probably crashed on startup: OOBE not dismissed: context deadline exceeded ... Unfortunately, it looks like I might be hitting a different issue. :-( Here's the end of the Chrome log. Note that it times out on getting server-backed state keys after a full day (!): ... [25304:25304:1205/151530.858917:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.CrosDisks.EnumerateAutoMountableDevices: object_path= /org/chromium/CrosDisks: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.[25304:25304:1205/151530.859110:ERROR:volume_manager.cc(943)] Failed to refresh disk mount manager [25304:25304:1206/151505.890177:WARNING:server_backed_state_keys_broker.cc(76)] Failed to obtain server-backed state keys. /var/log/messages is no help either (yes, syslog is using a different time zone): 2017-12-05T23:15:05.243209+00:00 INFO session_manager[24822]: [INFO:browser_job.cc(150)] Running child /opt/google/chrome/chrome ... 2017-12-05T23:15:05.244521+00:00 INFO session_manager[24822]: [INFO:session_manager_service.cc(224)] Browser is 25304 2017-12-05T23:15:05.244720+00:00 INFO session_manager[24822]: [INFO:child_exit_handler.cc(77)] Handling 25172 exit. 2017-12-05T23:15:05.244744+00:00 INFO session_manager[24822]: [INFO:session_manager_impl.cc(1407)] Processing generated key at /home/user/30e85910b346de99f40283c9f179fc89e8f9651f/key.pub 2017-12-05T23:15:05.264437+00:00 INFO session_manager[24822]: [INFO:policy_key.cc(120)] wrote 294 bytes to /var/lib/whitelist/owner.key 2017-12-05T23:15:05.264464+00:00 INFO session_manager[24822]: [INFO:policy_service.cc(139)] Persisted policy key to disk. 2017-12-05T23:15:05.270607+00:00 INFO session_manager[24822]: [INFO:policy_store.cc(69)] Persisted policy to disk. 2017-12-05T23:15:05.813933+00:00 WARNING session_manager[24822]: [WARNING:server_backed_state_key_generator.cc(216)] No device identifiers available, no state keys generated 2017-12-05T23:46:35.241265+00:00 INFO periodic_scheduler[26131]: crash_sender: running /sbin/crash_sender
,
Dec 18 2017
It was fairly unpleasant, but I finally managed to collect and symbolize a minidump! Here's the top of the stack from the aborting thread:
Crash reason: SIGABRT
Crash address: 0x3e800001681
Process uptime: not available
Thread 0 (crashed)
0 libc-2.23.so!raise [raise.c : 54 + 0x10]
rax = 0x0000000000000000 rdx = 0x0000000000000006
rcx = 0x00007a879c57fdd2 rbx = 0x00003676c9e809f0
rsi = 0x0000000000001681 rdi = 0x0000000000001681
rbp = 0x00007fffbe3884c0 rsp = 0x00007fffbe388398
r8 = 0x00003676ca9b81a5 r9 = 0x0000000000000001
r10 = 0x0000000000000008 r11 = 0x0000000000000206
r12 = 0x00003676ca9b81a5 r13 = 0x0000000000000288
r14 = 0x0000000000000048 r15 = 0x00007fffbe3889a0
rip = 0x00007a879c57fdd2
Found by: given as instruction pointer in context
1 libc-2.23.so!abort [abort.c : 89 + 0xa]
rbx = 0x00003676c9e809f0 rbp = 0x00007fffbe3884c0
rsp = 0x00007fffbe3883a0 r12 = 0x00003676ca9b81a5
r13 = 0x0000000000000288 r14 = 0x0000000000000048
r15 = 0x00007fffbe3889a0 rip = 0x00007a879c581bf6
Found by: call frame info
2 chrome!base::debug::BreakDebugger() [debugger_posix.cc : 258 + 0x5]
rbx = 0x00003676c9e809f0 rbp = 0x00007fffbe3884d0
rsp = 0x00007fffbe3884d0 r12 = 0x00003676ca9b81a5
r13 = 0x0000000000000288 r14 = 0x0000000000000048
r15 = 0x00007fffbe3889a0 rip = 0x00005685161323a5
Found by: call frame info
3 chrome!logging::LogMessage::~LogMessage() [callback.h : 94 + 0x9]
rbx = 0x00003676c9e809f0 rbp = 0x00007fffbe388960
rsp = 0x00007fffbe3884e0 r12 = 0x00003676ca9b81a5
r13 = 0x0000000000000288 r14 = 0x0000000000000048
r15 = 0x00007fffbe3889a0 rip = 0x0000568516149e09
Found by: call frame info
4 chrome!ProfileManager::GetLastUsedProfile(base::FilePath const&) [profile_manager.cc : 648 + 0x8]
rbx = 0x0000000000000000 rbp = 0x00007fffbe388af0
rsp = 0x00007fffbe388970 r12 = 0x00007fffbe388970
r13 = 0x00003676c9f08720 r14 = 0x00007fffbe3889a0
r15 = 0x00007fffbe388988 rip = 0x0000568515eb323c
Found by: call frame info
5 chrome!chromeos::LowDiskNotification::LowDiskSpace(unsigned long) [low_disk_notification.cc : 72 + 0x5]
rbx = 0x0000000000000000 rbp = 0x00007fffbe388c70
rsp = 0x00007fffbe388b00 r12 = 0x0000000029023000
r13 = 0x00003676c9f08720 r14 = 0x00003676ca77c0c0
r15 = 0x00007fffbe388cf8 rip = 0x000056851555a12b
Found by: call frame info
6 chrome!chromeos::(anonymous namespace)::CryptohomeClientImpl::LowDiskSpaceReceived(dbus::Signal*) [cryptohome_client.cc : 1228 + 0x3]
rbx = 0x0000000000000002 rbp = 0x00007fffbe388e40
rsp = 0x00007fffbe388c80 r12 = 0x00007fffbe388ee0
r13 = 0x00003676c9f08720 r14 = 0x00007fffbe388c80
r15 = 0x00007fffbe388cf8 rip = 0x0000568516c7dceb
Found by: call frame info
7 chrome!dbus::ObjectProxy::RunMethod(base::TimeTicks, std::__1::vector<base::RepeatingCallback<void (dbus::Signal*)>, std::__1::allocator<base::RepeatingCallback<void (dbus::Signal*)> > >, dbus::Signal*) [callback.h : 94 + 0x6]
rbx = 0x00003676cab83f80 rbp = 0x00007fffbe388eb0
rsp = 0x00007fffbe388e50 r12 = 0x00007fffbe388ee0
r13 = 0x00003676c9f08720 r14 = 0x00000000083e053d
r15 = 0x00003676c9e6e9c0 rip = 0x0000568516c9abf9
Found by: call frame info
...
,
Dec 18 2017
Thanks for digging it out. LowDiskNotification is a system notification. IMHO, it should either use the sign-in profile (ProfileHelper::GetSigninProfile) or use ProfileManager::GetActiveUserProfile(). GetLastUserProfile() is unsafe to call during user profile loading.
,
Dec 18 2017
thanks for debugging
,
Dec 19 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/847c3aafdbef649bf8abf02fecf4e62d14150b3b commit 847c3aafdbef649bf8abf02fecf4e62d14150b3b Author: Evan Stade <estade@chromium.org> Date: Tue Dec 19 20:46:03 2017 Revert "[CrOS] Make LowDiskNotification use NotificationDisplayService" This reverts commit e9374ae205116caa8c5bcea63b01ae53724b2961. This caused a crash at startup, and the easiest thing to merge to m64 is a revert, hence this patch. NotificationDisplayService will be reinstated in a follow-up change. TBR=jamescook@chromium.org Bug: 791200 Change-Id: I1643f2598bc0acea43a9cf2fa0e523f536f69c89 Reviewed-on: https://chromium-review.googlesource.com/832990 Commit-Queue: Evan Stade <estade@chromium.org> Reviewed-by: Evan Stade <estade@chromium.org> Cr-Commit-Position: refs/heads/master@{#525136} [modify] https://crrev.com/847c3aafdbef649bf8abf02fecf4e62d14150b3b/chrome/browser/chromeos/ui/low_disk_notification.cc [modify] https://crrev.com/847c3aafdbef649bf8abf02fecf4e62d14150b3b/chrome/browser/chromeos/ui/low_disk_notification.h [modify] https://crrev.com/847c3aafdbef649bf8abf02fecf4e62d14150b3b/chrome/browser/chromeos/ui/low_disk_notification_unittest.cc
,
Dec 20 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/be3aba998ba47dfa1cd8b9de02136765b39ee311 commit be3aba998ba47dfa1cd8b9de02136765b39ee311 Author: Evan Stade <estade@chromium.org> Date: Wed Dec 20 17:46:29 2017 Make LowDiskNotification use the NotificationDisplayService for system notifications (i.e. the sign in profile). As per xiyuan&, during login, it's not safe to access the last used profile. And, as he points out, this is a system-level notification. NDS::GetForSystemNotifications was introduced recently and is a good fit. Bug: 791200 Change-Id: I6ecd2660a42a9a35a47643f2c166ee039b319b99 Reviewed-on: https://chromium-review.googlesource.com/833019 Commit-Queue: Evan Stade <estade@chromium.org> Reviewed-by: Dan Erat <derat@chromium.org> Reviewed-by: Xiyuan Xia <xiyuan@chromium.org> Reviewed-by: James Cook <jamescook@chromium.org> Cr-Commit-Position: refs/heads/master@{#525363} [modify] https://crrev.com/be3aba998ba47dfa1cd8b9de02136765b39ee311/chrome/browser/chromeos/ui/low_disk_notification.cc [modify] https://crrev.com/be3aba998ba47dfa1cd8b9de02136765b39ee311/chrome/browser/chromeos/ui/low_disk_notification.h [modify] https://crrev.com/be3aba998ba47dfa1cd8b9de02136765b39ee311/chrome/browser/chromeos/ui/low_disk_notification_unittest.cc
,
Dec 20 2017
requesting merge of revert in c10
,
Dec 20 2017
Is this a confirmed regression since M63?
,
Dec 20 2017
The crash stack above would have been impossible before https://crrev.com/e9374ae205116caa8c5bcea63b01ae53724b2961 and that landed squarely in the middle of the m64 timeframe, so yes.
,
Dec 21 2017
This bug requires manual review: Reverts referenced in bugdroid comments after merge request. Please contact the milestone owner if you have questions. Owners: cmasso@(Android), cmasso@(iOS), kbleicher@(ChromeOS), abdulsyed@(Desktop) For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
,
Dec 21 2017
note this is my second to last day in the office and then I'm gone till jan 8, so it would be good to merge today or tomorrow.
,
Dec 21 2017
+Kevin for merge review.
,
Dec 21 2017
Approving merge to M64 Chrome OS.
,
Dec 21 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/cb9783db17174a8fa7bb451b3cb6e6dc43de7407 commit cb9783db17174a8fa7bb451b3cb6e6dc43de7407 Author: Evan Stade <estade@chromium.org> Date: Thu Dec 21 20:05:04 2017 Revert "[CrOS] Make LowDiskNotification use NotificationDisplayService" This reverts commit e9374ae205116caa8c5bcea63b01ae53724b2961. This caused a crash at startup, and the easiest thing to merge to m64 is a revert, hence this patch. NotificationDisplayService will be reinstated in a follow-up change. TBR=estade@chromium.org, jamescook@chromium.org (cherry picked from commit 847c3aafdbef649bf8abf02fecf4e62d14150b3b) Bug: 791200 Change-Id: I1643f2598bc0acea43a9cf2fa0e523f536f69c89 Reviewed-on: https://chromium-review.googlesource.com/832990 Commit-Queue: Evan Stade <estade@chromium.org> Reviewed-by: Evan Stade <estade@chromium.org> Cr-Original-Commit-Position: refs/heads/master@{#525136} Reviewed-on: https://chromium-review.googlesource.com/840616 Cr-Commit-Position: refs/branch-heads/3282@{#324} Cr-Branched-From: 5fdc0fab22ce7efd32532ee989b223fa12f8171e-refs/heads/master@{#520840} [modify] https://crrev.com/cb9783db17174a8fa7bb451b3cb6e6dc43de7407/chrome/browser/chromeos/ui/low_disk_notification.cc [modify] https://crrev.com/cb9783db17174a8fa7bb451b3cb6e6dc43de7407/chrome/browser/chromeos/ui/low_disk_notification.h [modify] https://crrev.com/cb9783db17174a8fa7bb451b3cb6e6dc43de7407/chrome/browser/chromeos/ui/low_disk_notification_unittest.cc
,
Dec 21 2017
thanks. It didn't merge completely cleanly so I hope I resolved conflicts correctly. If not, the fix should be easy.
,
Feb 14 2018
assuming fixed |
|||||||||||||||||||||||
►
Sign in to add a comment |
|||||||||||||||||||||||
Comment 1 by xiy...@chromium.org
, Dec 4 2017