Flaky: login_OwnershipNotRetaken |
||||||||||||
Issue descriptionThis 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
,
Dec 13 2017
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
,
Dec 13 2017
/cc some folks touched cryptohome recently. maajid, any thoughts on how to investigate this further?
,
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
,
Dec 13 2017
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.
,
Dec 13 2017
,
Dec 13 2017
,
Dec 13 2017
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)
,
Dec 13 2017
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)
,
Dec 13 2017
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
,
Dec 13 2017
Judging by #10, it is a dup of b/69871115, issue 794403.
,
Dec 13 2017
,
Dec 13 2017
,
Dec 14 2017
Another example: https://luci-milo.appspot.com/buildbot/chromeos/lumpy-paladin/30448
,
Dec 14 2017
Another example: https://luci-milo.appspot.com/buildbot/chromeos/lumpy-paladin/30450
,
Dec 15 2017
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.
,
Dec 16 2017
Minimal CL to deal with crashes is submitted for review - see http://b/69871115#comment20.
,
Dec 16 2017
Issue 779207 has been merged into this issue.
,
Dec 16 2017
Temporarily assigning back to ejcaruso@, while I'm away next week, to see CL to landing and verify it addresses all issues.
,
Dec 16 2017
And merging into a more generically formulated issue 794403. |
||||||||||||
►
Sign in to add a comment |
||||||||||||
Comment 1 by michae...@chromium.org
, Dec 13 2017Components: UI>Shell>StartScreen Tests>Flaky
Labels: Hotlist-CrOS-Sheriffing OS-Chrome