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

Issue 794375 link

Starred by 3 users

Issue metadata

Status: Duplicate
Owner:
Closed: Dec 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

Flaky: login_OwnershipNotRetaken

Project Member Reported by dgarr...@chromium.org, Dec 13 2017

Issue description

This test appears to be relatively flaky.

For this build, it failed for 3 tries, on multiple DUTs with no relevant CLs being tested.

https://luci-milo.appspot.com/buildbot/chromeos/lumpy-paladin/30478

In every case, the failures looked identical (to me):

http://cautotest-prod.corp.google.com/afe/#tab_id=view_job&object_id=162063225



12/12 07:44:59.638 DEBUG|      global_hooks:0056| 'rsync --no-perms --chmod=ugo+r -a --safe-links --exclude=/log/**autoserv* /var/log /usr/local/autotest/results/default/login_OwnershipNotRetaken/sysinfo/var'
12/12 07:44:59.663 INFO |              test:0928| after_hook completed
12/12 07:44:59.664 ERROR|          parallel:0026| child process failed
12/12 07:44:59.670 DEBUG|          parallel:0030| Traceback (most recent call last):
12/12 07:44:59.671 DEBUG|          parallel:0030|   File "/usr/local/autotest/bin/parallel.py", line 18, in fork_start
12/12 07:44:59.671 DEBUG|          parallel:0030|     l()
12/12 07:44:59.671 DEBUG|          parallel:0030|   File "/usr/local/autotest/bin/job.py", line 488, in <lambda>
12/12 07:44:59.671 DEBUG|          parallel:0030|     l = lambda : test.runtest(self, url, tag, args, dargs)
12/12 07:44:59.672 DEBUG|          parallel:0030|   File "/usr/local/autotest/bin/test.py", line 117, in runtest
12/12 07:44:59.672 DEBUG|          parallel:0030|     job.sysinfo.log_after_each_iteration)
12/12 07:44:59.672 DEBUG|          parallel:0030|   File "/usr/local/autotest/common_lib/test.py", line 919, in runtest
12/12 07:44:59.672 DEBUG|          parallel:0030|     mytest._exec(args, dargs)
12/12 07:44:59.672 DEBUG|          parallel:0030|   File "/usr/local/autotest/common_lib/test.py", line 674, in _exec
12/12 07:44:59.673 DEBUG|          parallel:0030|     raise error.UnhandledTestError(e)
12/12 07:44:59.673 DEBUG|          parallel:0030| UnhandledTestError: Unhandled DBusException: org.freedesktop.DBus.Error.ServiceUnknown: The name :1.13 was not provided by any .service files
12/12 07:44:59.673 DEBUG|          parallel:0030| Traceback (most recent call last):
12/12 07:44:59.673 DEBUG|          parallel:0030|   File "/usr/local/autotest/common_lib/test.py", line 665, in _exec
12/12 07:44:59.674 DEBUG|          parallel:0030|     _cherry_pick_call(self.cleanup, *args, **dargs)
12/12 07:44:59.674 DEBUG|          parallel:0030|   File "/usr/local/autotest/common_lib/test.py", line 746, in _cherry_pick_call
12/12 07:44:59.674 DEBUG|          parallel:0030|     return func(*p_args, **p_dargs)
12/12 07:44:59.674 DEBUG|          parallel:0030|   File "/usr/local/autotest/tests/login_OwnershipNotRetaken/login_OwnershipNotRetaken.py", line 71, in cleanup
12/12 07:44:59.674 DEBUG|          parallel:0030|     self._cryptohome_proxy.remove(self._TEST_USER)
12/12 07:44:59.675 DEBUG|          parallel:0030|   File "/usr/local/autotest/cros/cryptohome.py", line 673, in remove
12/12 07:44:59.675 DEBUG|          parallel:0030|     user)['return_status']
12/12 07:44:59.675 DEBUG|          parallel:0030|   File "/usr/local/autotest/cros/cryptohome.py", line 607, in __async_call
12/12 07:44:59.676 DEBUG|          parallel:0030|     out = self.__call(method, *args)
12/12 07:44:59.676 DEBUG|          parallel:0030|   File "/usr/local/autotest/cros/cryptohome.py", line 583, in __call
12/12 07:44:59.676 DEBUG|          parallel:0030|     raise e
12/12 07:44:59.677 DEBUG|          parallel:0030| DBusException: org.freedesktop.DBus.Error.ServiceUnknown: The name :1.13 was not provided by any .service files


The flakey test dashboard shows it to have issues on multiple boards:

guado_moblab	lumpy	mccloud	peppy	rikku

https://wmatrix.googleplex.com/retry_teststats/?days_back=30&tests=login_OwnershipNotRetaken




 
Cc: alemate@chromium.org achuith@chromium.org vadimt@chromium.org michae...@chromium.org
Components: UI>Shell>StartScreen Tests>Flaky
Labels: Hotlist-CrOS-Sheriffing OS-Chrome
same flake on caroline-tot-chrome-pfq-informational: https://ci.chromium.org/buildbot/chromeos.chrome/caroline-tot-chrome-pfq-informational/532
with my limited knowledge of dbus, looks like the connection it's expecting on :1.13 is not open?

I don't see a crash report on the paladin builder, but the pfq-informational logs have a cryptohome.d dump for a SIGABRT in ChapsProxyImpl called from cryptohome::Mount::InsertPkcs11Token(): https://storage.cloud.google.com/chromeos-autotest-results/162288268-chromeos-test/chromeos6-row2-rack23-host9/debug/cryptohomed.20171213.091501.2255.dmp.txt?_ga=2.46386919.-1729301091.1506362054

The ui logs show cryptohome issues, e.g. https://storage.cloud.google.com/chromeos-autotest-results/162063225-chromeos-test/chromeos6-row2-rack7-host19/login_OwnershipNotRetaken/sysinfo/var/log/ui/ui.20171212-074430?_ga=2.10200821.-1729301091.1506362054:


[4261:4301:1212/074432.272457:ERROR:service_manager.cc(158)] Connection InterfaceProviderSpec prevented service: content_renderer from binding interface: blink::mojom::ReportingServiceProxy exposed by: content_browser
[4261:4261:1212/074434.120888:ERROR:device_event_log_impl.cc(156)] [07:44:34.120] Network: network_state_handler.cc:182 SetTechnologyEnabled() called for the Tether DeviceState, but the current state was: 0
[4261:4261:1212/074434.848532:ERROR:device_event_log_impl.cc(156)] [07:44:34.848] Login: homedir_methods.cc:274 HomedirMethods MountEx error (CryptohomeErrorCode): 1
[4261:4261:1212/074434.848606:ERROR:device_event_log_impl.cc(156)] [07:44:34.848] Login: cryptohome_authenticator.cc:932 Cryptohome failure: state(AuthState)=1, code(cryptohome::MountError)=32
[1212/074436:INFO:policy_key.cc(51)] No policy key on disk at /home/user/3682c1682a70d2bfa47e0beb27c22e579d061ee8/key.pub
[1212/074436:INFO:keygen_worker.cc(46)] Generating Owner key.
[4261:4261:1212/074436.386966:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.CryptohomeInterface.Pkcs11GetTpmTokenInfo: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.NoReply: Message recipient disconnected from message bus without replying
[4261:4261:1212/074436.491113:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.CryptohomeInterface.Pkcs11GetTpmTokenInfo: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.Cryptohome was not provided by any .service files
[4261:4261:1212/074436.693856:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.CryptohomeInterface.Pkcs11GetTpmTokenInfo: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.Cryptohome was not provided by any .service files
[4261:4261:1212/074437.073652:ERROR:input_method_manager_impl.cc(1031)] IMEEngine for "jkghodnilhceideoidjikpgommlajknk" is not registered
[4261:4261:1212/074437.275923:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.CryptohomeInterface.Pkcs11GetTpmTokenInfo: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.Cryptohome was not provided by any .service files
[4261:4284:1212/074437.783133:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.CryptohomeInterface.TpmIsEnabled: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.Cryptohome was not provided by any .service files
[4261:4261:1212/074438.003722:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.CryptohomeInterface.RemoveKeyEx: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.Cryptohome was not provided by any .service files
[4261:4261:1212/074438.003782:ERROR:easy_unlock_remove_keys_operation.cc(78)] Easy unlock remove keys operation failed, code=1
[4261:4261:1212/074438.194979:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.CryptohomeInterface.Pkcs11GetTpmTokenInfo: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.Cryptohome was not provided by any .service files
[4261:4261:1212/074438.527268:ERROR:customization_document.cc(623)] Customization manifest is missing on server: https://ssl.gstatic.com/chrome/chromeos-customization/lumpy.json
[4261:4261:1212/074439.796112:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.CryptohomeInterface.Pkcs11GetTpmTokenInfo: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.Cryptohome was not provided by any .service files
[1212/074439:INFO:keygen_worker.cc(53)] Writing Owner key to /home/user/3682c1682a70d2bfa47e0beb27c22e579d061ee8/key.pub
[1212/074439:INFO:policy_key.cc(120)] wrote 294 bytes to /home/user/3682c1682a70d2bfa47e0beb27c22e579d061ee8/key.pub

Cc: maajid@chromium.org hidehiko@chromium.org
/cc some folks touched cryptohome recently. maajid, any thoughts on how to investigate this further?

Comment 4 by ecgh@chromium.org, Dec 13 2017

Another failure on lumpy-paladin:

https://luci-milo.appspot.com/buildbot/chromeos/lumpy-paladin/30488

login_OwnershipNotRetaken: retry_count: 2, ERROR: Unhandled DBusException: org.freedesktop.DBus.Error.ServiceUnknown: The name :1.13 was not provided by any .service files
Labels: -Pri-3 Pri-1
Owner: dtor@chromium.org
Passing to a sheriff to find a product owner. This looks like a real test failure (if obscure) that is hitting multiple boards and affecting multiple builds.

If the fail rate is high enough, we should disable the test until it can be addressed.
Cc: r...@chromium.org
Cc: apronin@chromium.org
2017-12-13T17:43:05.306545+00:00 WARNING crash_reporter[4916]: [user] Received crash notification for cryptohomed[1556] sig 6, user 0 (developer build - not testing - always dumping)

2017-12-13T17:42:59.665647+00:00 INFO session_manager[4648]: [INFO:system_utils_impl.cc(93)] Sending 9 to 4661 as 0
2017-12-13T17:42:59.665923+00:00 INFO session_manager[4648]: [INFO:browser_job.cc(180)] Cleaned up child 4661
2017-12-13T17:42:59.666477+00:00 INFO session_manager[4648]: [INFO:browser_job.cc(147)] Running child /opt/google/chrome/chrome --ppapi-flash-path=/opt/google/chrome/pepper/libpepflashplayer.so --ppapi-flash-version=28.0.0.129 --ui-prioritize-in-gpu-process --use-gl=egl --gpu-sandbox-failures-fatal=yes --enable-logging --log-level=1 --use-cras --enable-wayland-server --user-data-dir=/home/chronos --max-unused-resource-memory-usage-percentage=5 --system-developer-mode --login-profile=user --has-chromeos-keyboard --default-wallpaper-large=/usr/share/chromeos-assets/wallpaper/default_large.jpg --default-wallpaper-small=/usr/share/chromeos-assets/wallpaper/default_small.jpg --child-wallpaper-large=/usr/share/chromeos-assets/wallpaper/child_large.jpg --child-wallpaper-small=/usr/share/chromeos-assets/wallpaper/child_small.jpg --guest-wallpaper-large=/usr/share/chromeos-assets/wallpaper/guest_large.jpg --guest-wallpaper-small=/usr/share/chromeos-assets/wallpaper/guest_small.jpg --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 --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 --allow-failed-policy-fetch-for-test --oobe-skip-postlogin --disable-logging-redirect --disable-gaia-services --testing-channel=NamedTestingInterface:/tmp/.org.chromium.Chromium.K8rwdB/.org.chromium.Chromium.DF1qdj --vmodule=automatic_reboot_manager=1,tablet_power_button_controller=1,*chromeos/login/*=1,auto_enrollment_controller=1,*plugin*=2,*zygote*=1,*/ui/ozone/*=1,*/ui/display/manager/chromeos/*=1,*night_light*=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
2017-12-13T17:42:59.673448+00:00 INFO session_manager[4648]: [INFO:session_manager_service.cc(224)] Browser is 4711
2017-12-13T17:43:00.113909+00:00 INFO kernel: [  161.939261] [drm] Adding LVDS downclock mode
2017-12-13T17:43:00.201917+00:00 DEBUG kernel: [  162.026935] ieee80211 phy0: device now idle
2017-12-13T17:43:01.552905+00:00 INFO kernel: [  163.377127] [drm] Adding LVDS downclock mode
2017-12-13T17:43:02.804774+00:00 DEBUG kernel: [  164.626330] ieee80211 phy0: device no longer idle - scanning
2017-12-13T17:43:03.973408+00:00 INFO cryptohomed[1556]: HasAuthorization: TPM Owner password not available.
2017-12-13T17:43:03.973436+00:00 ERR cryptohomed[1556]: Destroy() called with insufficient authorization.
2017-12-13T17:43:03.995430+00:00 WARNING cryptohomed[1556]: Could not load the device policy file.
2017-12-13T17:43:04.027899+00:00 INFO kernel: [  165.850599] tpm_tis tpm_tis: command 0x15 (size 14) returned code 0x0
2017-12-13T17:43:04.078932+00:00 INFO kernel: [  165.901573] tpm_tis tpm_tis: command 0x14 (size 34) returned code 0x0
2017-12-13T17:43:04.078345+00:00 WARNING cryptohomed[1556]: Could not load the device policy file.
2017-12-13T17:43:04.078974+00:00 INFO cryptohomed[1556]: TPM error 0x2020 (Key not found in persistent storage): LoadKeyByUuid: failed LoadKeyByUUID
2017-12-13T17:43:04.079001+00:00 WARNING cryptohomed[1556]: Canceled creating cryptohome key - TPM is not ready.
2017-12-13T17:43:04.689413+00:00 INFO session_manager[4648]: [INFO:upstart_signal_emitter.cc(35)] Emitting login-prompt-visible Upstart signal
2017-12-13T17:43:04.759674+00:00 INFO session_manager[4648]: [INFO:server_backed_state_key_generator.cc(126)] Stable device secret missing!
2017-12-13T17:43:05.019476+00:00 INFO cryptohomed[1556]: TPM error 0x2020 (Key not found in persistent storage): LoadKeyByUuid: failed LoadKeyByUUID
2017-12-13T17:43:05.019566+00:00 WARNING cryptohomed[1556]: Canceled creating cryptohome key - TPM is not ready.
2017-12-13T17:43:05.020251+00:00 INFO cryptohomed[1556]: Migrated (or created) user directory: /home/.shadow/487242c5287868c9ea92a28a26efd9c310a67fd9/vault
2017-12-13T17:43:05.028843+00:00 INFO cryptohomed[1556]: Creating pass-through directories /home/.shadow/487242c5287868c9ea92a28a26efd9c310a67fd9/vault/user/Cache
2017-12-13T17:43:05.029499+00:00 INFO cryptohomed[1556]: Creating pass-through directories /home/.shadow/487242c5287868c9ea92a28a26efd9c310a67fd9/vault/user/Downloads
2017-12-13T17:43:05.029650+00:00 INFO cryptohomed[1556]: Creating pass-through directories /home/.shadow/487242c5287868c9ea92a28a26efd9c310a67fd9/vault/user/GCache
2017-12-13T17:43:05.029779+00:00 INFO cryptohomed[1556]: Creating pass-through directories /home/.shadow/487242c5287868c9ea92a28a26efd9c310a67fd9/vault/user/GCache/v1
2017-12-13T17:43:05.029934+00:00 INFO cryptohomed[1556]: Creating pass-through directories /home/.shadow/487242c5287868c9ea92a28a26efd9c310a67fd9/vault/user/GCache/v1/blobs
2017-12-13T17:43:05.030069+00:00 INFO cryptohomed[1556]: Creating pass-through directories /home/.shadow/487242c5287868c9ea92a28a26efd9c310a67fd9/vault/user/GCache/v1/tmp
2017-12-13T17:43:05.046535+00:00 INFO cryptohomed[1556]: RecursiveCopy: /home/.shadow/487242c5287868c9ea92a28a26efd9c310a67fd9/mount/user/log
2017-12-13T17:43:05.047451+00:00 INFO cryptohomed[1556]: RecursiveCopy: /home/.shadow/487242c5287868c9ea92a28a26efd9c310a67fd9/mount/user/.pki
2017-12-13T17:43:05.048391+00:00 INFO cryptohomed[1556]: RecursiveCopy: /home/.shadow/487242c5287868c9ea92a28a26efd9c310a67fd9/mount/user/.pki/nssdb
2017-12-13T17:43:05.069598+00:00 INFO cryptohomed[1556]: RecursiveCopy: /home/.shadow/487242c5287868c9ea92a28a26efd9c310a67fd9/mount/user/.ssh
2017-12-13T17:43:05.094330+00:00 INFO session_manager[4648]: [INFO:policy_key.cc(51)] No policy key on disk at /home/root/487242c5287868c9ea92a28a26efd9c310a67fd9/session_manager/policy/key
2017-12-13T17:43:05.110980+00:00 INFO cryptohomed[1556]: Putting a Pkcs11_Initialize on the mount thread.
2017-12-13T17:43:05.120571+00:00 INFO chapsd[1459]: Opening database in: /home/root/487242c5287868c9ea92a28a26efd9c310a67fd9/chaps
2017-12-13T17:43:05.138500+00:00 ERR session_manager[4648]: [ERROR:nss_util.cc(145)] Not checking key because size is 0
2017-12-13T17:43:05.138822+00:00 WARNING session_manager[4648]: [WARNING:device_policy_service.cc(454)] Could not verify that owner key belongs to this user.
2017-12-13T17:43:05.139647+00:00 ERR session_manager[4648]: [ERROR:dbus_util.cc(13)] CreateError(...): Domain=dbus, Code=org.chromium.SessionManagerInterface.PubkeySetIllegal, Message=Could not verify that owner key belongs to this user.
2017-12-13T17:43:05.149073+00:00 INFO session_manager[4648]: [INFO:upstart_signal_emitter.cc(35)] Emitting start-user-session Upstart signal
2017-12-13T17:43:05.149199+00:00 INFO session_manager[4648]: [INFO:session_manager_impl.cc(601)] Starting user session
2017-12-13T17:43:05.149269+00:00 INFO session_manager[4648]: [INFO:session_manager_impl.cc(605)] emitting D-Bus signal SessionStateChanged:started
2017-12-13T17:43:05.151090+00:00 INFO session_manager[4648]: [INFO:key_generator.cc(57)] Generating key at /home/user/487242c5287868c9ea92a28a26efd9c310a67fd9/key.pub using nssdb under /home/user/487242c5287868c9ea92a28a26efd9c310a67fd9
2017-12-13T17:43:05.153985+00:00 WARNING session_manager[4648]: [WARNING:policy_store.cc(36)] Policy file at /home/root/487242c5287868c9ea92a28a26efd9c310a67fd9/session_manager/policy/policy does not exist. Continuing anyway.
2017-12-13T17:43:05.246624+00:00 INFO chapsd[1459]: Importing opencryptoki objects.
2017-12-13T17:43:05.246729+00:00 WARNING chapsd[1459]: Did not find any opencryptoki objects to import.
2017-12-13T17:43:05.258125+00:00 INFO chapsd[1459]: Slot 1 ready for token at /home/root/487242c5287868c9ea92a28a26efd9c310a67fd9/chaps
2017-12-13T17:43:05.259661+00:00 CRIT cryptohomed[1556]: Check failed: this == g_top_manager (0x7f75b40053d0 vs. 0x7f75c59050a0)#012/usr/lib64/libbase-core-395517.so(base::debug::StackTrace::StackTrace()+0x13) [0x7f75c4da6fd3]#012
2017-12-13T17:43:05.260164+00:00 INFO chapsd[1459]: Initializing key hierarchy for token at /home/root/487242c5287868c9ea92a28a26efd9c310a67fd9/chaps
2017-12-13T17:43:05.264240+00:00 ERR shill[1502]: [ERROR:crypto_des_cbc.cc(107)] Unable to load key matter from /var/lib/whitelist/owner.key
2017-12-13T17:43:05.284211+00:00 INFO crash_reporter[4916]: libminijail[4916]: mount /dev/log -> /dev/log type ''
2017-12-13T17:43:05.288148+00:00 ERR shill[1502]: [ERROR:crypto_des_cbc.cc(107)] Unable to load key matter from /var/lib/whitelist/owner.key
2017-12-13T17:43:05.296902+00:00 INFO kernel: [  167.118773] tpm_tis tpm_tis: command 0x46 (size 14) returned code 0x0
2017-12-13T17:43:05.306458+00:00 WARNING crash_reporter[4916]: Could not load the device policy file.
2017-12-13T17:43:05.306545+00:00 WARNING crash_reporter[4916]: [user] Received crash notification for cryptohomed[1556] sig 6, user 0 (developer build - not testing - always dumping)
2017-12-13T17:43:05.316193+00:00 INFO crash_reporter[4916]: State of crashed process [1556]: D (disk sleep)
It looks like this:

2017-12-13T17:43:05.259661+00:00 CRIT cryptohomed[1556]: Check failed: this == g_top_manager (0x7f75b40053d0 vs. 0x7f75c59050a0)#012/usr/lib64/libbase-core-395517.so(base::debug::StackTrace::StackTrace()+0x13) [0x7f75c4da6fd3]#012

Judging by #10, it is a dup of b/69871115, issue 794403.
Cc: ejcaruso@chromium.org

Comment 13 by dtor@chromium.org, Dec 13 2017

Owner: ejcaruso@chromium.org
Owner: apronin@chromium.org
If this is a dup as in c#11 then Andrey is working on it so I'm assigning to him. If there's stuff left to do by EOD today I'll take over since he'll be out, but he's working on it at the moment.
Status: Started (was: Untriaged)
Minimal CL to deal with crashes is submitted for review - see http://b/69871115#comment20.
Cc: warx@chromium.org athilenius@chromium.org xixuan@chromium.org malaykeshav@chromium.org jdufault@chromium.org slavamn@chromium.org
 Issue 779207  has been merged into this issue.
Owner: ejcaruso@chromium.org
Temporarily assigning back to ejcaruso@, while I'm away next week, to see CL to landing and verify it addresses all issues.

Mergedinto: 794403
Status: Duplicate (was: Started)
And merging into a more generically formulated issue 794403.

Sign in to add a comment