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

Issue 880818 link

Starred by 4 users
Status: Duplicate
Merged: issue 875263
Owner:
apronin@chromium.org
Closed: Oct 9
Cc:
apronin@chromium.org
xiy...@chromium.org
mnissler@chromium.org
█ jrbarnette@chromium.org
jclinton@chromium.org
jdufault@chromium.org
nya@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

Login tests time out consistently on a rikku DUT while waiting for cryptohome mount

Project Member Reported by derat@chromium.org, Sep 5 
The ui.ChromeCrashLoggedIn and ui.ChromeLogin tests both failed three days ago in a rikku-release run on chromeos4-row3-rack5-host1 at http://stainless/browse/chromeos-autotest-results/233346142-chromeos-test/ :

2018/09/02 07:02:05 Started test ui.ChromeCrashLoggedIn
2018/09/02 07:02:05 [07:02:04.794] Restarting ui job
...
2018/09/02 07:02:10 [07:02:09.317] Logging in as user "testuser@gmail.com"
2018/09/02 07:02:10 [07:02:09.405] Waiting for cryptohome /home/user/1ee67d699b6739b536f86486003059539dba35ce
2018/09/02 07:04:02 [07:04:01.835] cryptohome status:
{
   "installattrs": {
      "first_install": false,
      "initialized": false,
      "invalid": false,
      "lockbox_index": 536870916,
      "lockbox_nvram_version": 2,
      "secure": false,
      "size": 0,
      "version": 1
   },
   "mounts": [  ],
   "tpm": {
      "being_owned": false,
      "can_connect": true,
      "can_decrypt": false,
      "can_encrypt": false,
      "can_load_srk": false,
      "can_load_srk_pubkey": false,
      "enabled": true,
      "has_context": true,
      "has_cryptohome_key": false,
      "has_key_handle": false,
      "last_error": 8224,
      "owned": false,
      "srk_vulnerable_roca": false
   }
}
2018/09/02 07:04:02 [07:04:01.866] /sys/class/misc/tpm0/device/owned contains "0"
2018/09/02 07:04:02 [07:04:01.866] Error at chrome_crash_logged_in.go:27: Chrome login failed: /home/user/1ee67d699b6739b536f86486003059539dba35ce not mounted: context deadline exceeded
...
2018/09/02 07:04:05 Started test ui.ChromeLogin
2018/09/02 07:04:05 [07:04:04.086] Restarting ui job
...
2018/09/02 07:04:09 [07:04:08.702] Logging in as user "testuser@gmail.com"
2018/09/02 07:04:09 [07:04:08.766] Waiting for cryptohome /home/user/1ee67d699b6739b536f86486003059539dba35ce
2018/09/02 07:06:02 [07:06:01.292] 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/09/02 07:06:02 [07:06:01.328] /sys/class/misc/tpm0/device/owned contains "1"
2018/09/02 07:06:02 [07:06:01.332] Error at chrome_login.go:72: Chrome login failed: /home/user/1ee67d699b6739b536f86486003059539dba35ce not mounted: context deadline exceeded

This DUT doesn't appear to match the state that was described at  https://crbug.com/864282#c17 .

After the first failure, tpm.owned and tpm.being_owned were both false and /sys/class/misc/tpm0/device/owned contained 0.

After the second failure, tpm.owned was true, tpm.being_owned was false, and /sys/class/misc/tpm0/device/owned contained 1.

Here are the cryptohomed and TPM entries from /var/log/messages during these failures, I think:

2018-09-02T07:02:09.394272-07:00 ERR cryptohomed[724]: TpmIsReady: is not owned.
2018-09-02T07:02:09.394292-07:00 ERR cryptohomed[724]: HasAuthorization: TPM not ready.
2018-09-02T07:02:09.394302-07:00 ERR cryptohomed[724]: Destroy() called with insufficient authorization.
2018-09-02T07:02:09.521026-07:00 INFO session_manager[4685]: [INFO:server_backed_state_key_generator.cc(126)] Stable device secret missing!
2018-09-02T07:04:01.867259-07:00 INFO kernel: [  302.618824] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-09-02T07:04:01.942091-07:00 INFO session_manager[4685]: [INFO:browser_job.cc(167)] Terminating browser process 4700 with signal 15: exiting cleanly
2018-09-02T07:04:01.942248-07:00 INFO session_manager[4685]: [INFO:system_utils_impl.cc(94)] Sending 15 to 4700 as 1000
2018-09-02T07:04:02.206685-07:00 INFO session_manager[4685]: [INFO:session_manager_service.cc(481)] SessionManagerService quitting run loop
...
2018-09-02T07:04:06.018832-07:00 INFO kernel: [  306.768902] tpm_tis tpm_tis: command 0x7c (size 30) returned code 0x0
2018-09-02T07:04:06.067824-07:00 INFO kernel: [  306.817863] tpm_tis tpm_tis: command 0x7c (size 30) returned code 0x0
2018-09-02T07:04:06.117166-07:00 INFO kernel: [  306.866842] tpm_tis tpm_tis: command 0x7c (size 30) returned code 0x0
2018-09-02T07:04:06.141463-07:00 WARNING tcsd[689]: TSS: Unloading a public key of size 0!
2018-09-02T07:04:06.142167-07:00 INFO kernel: [  306.892225] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:07.188205-07:00 INFO kernel: [  307.938576] tpm_tis tpm_tis: command 0xd (size 624) returned code 0x0
2018-09-02T07:04:07.225161-07:00 INFO kernel: [  307.974787] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:07.268164-07:00 INFO kernel: [  308.017833] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:07.354186-07:00 INFO kernel: [  308.103838] tpm_tis tpm_tis: command 0x66 (size 55) returned code 0x0
2018-09-02T07:04:07.390206-07:00 INFO kernel: [  308.139705] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:07.445330-07:00 INFO kernel: [  308.194813] tpm_tis tpm_tis: command 0xb (size 36) returned code 0x0
2018-09-02T07:04:07.553178-07:00 INFO kernel: [  308.302833] tpm_tis tpm_tis: command 0x10 (size 79) returned code 0x0
2018-09-02T07:04:07.595162-07:00 INFO kernel: [  308.344605] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:07.619186-07:00 INFO kernel: [  308.368692] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:07.704168-07:00 INFO kernel: [  308.453713] tpm_tis tpm_tis: command 0x66 (size 55) returned code 0x0
2018-09-02T07:04:07.740185-07:00 INFO kernel: [  308.489603] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:07.765184-07:00 INFO kernel: [  308.514651] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:07.861163-07:00 INFO kernel: [  308.610656] tpm_tis tpm_tis: command 0x3f (size 72) returned code 0x0
2018-09-02T07:04:07.898522-07:00 INFO kernel: [  308.647544] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:07.923175-07:00 INFO kernel: [  308.672594] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:08.020161-07:00 INFO kernel: [  308.770198] tpm_tis tpm_tis: command 0x21 (size 59) returned code 0x0
2018-09-02T07:04:08.056175-07:00 INFO kernel: [  308.805476] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:08.087214-07:00 INFO kernel: [  308.836523] tpm_tis tpm_tis: command 0x15 (size 14) returned code 0x0
2018-09-02T07:04:08.149942-07:00 INFO kernel: [  308.898552] tpm_tis tpm_tis: command 0xb (size 36) returned code 0x0
2018-09-02T07:04:08.367164-07:00 INFO kernel: [  309.117171] tpm_tis tpm_tis: command 0x17 (size 143) returned code 0x0
2018-09-02T07:04:08.403165-07:00 INFO kernel: [  309.152336] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:08.472215-07:00 INFO kernel: [  309.221421] tpm_tis tpm_tis: command 0xb (size 36) returned code 0x0
2018-09-02T07:04:08.576162-07:00 INFO kernel: [  309.325373] tpm_tis tpm_tis: command 0x10 (size 79) returned code 0x0
2018-09-02T07:04:08.613160-07:00 INFO kernel: [  309.362357] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:08.620210-07:00 ERR cryptohomed[724]: Taking TPM ownership took 2661ms
2018-09-02T07:04:08.620446-07:00 INFO cryptohomed[724]: Configuring TPM, ownership taken: 1.
2018-09-02T07:04:08.654163-07:00 INFO kernel: [  309.403328] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:08.685168-07:00 INFO kernel: [  309.434315] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:08.721166-07:00 INFO kernel: [  309.470302] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:08.776166-07:00 INFO kernel: [  309.525316] tpm_tis tpm_tis: command 0xb (size 36) returned code 0x0
2018-09-02T07:04:08.849721-07:00 INFO session_manager[5454]: [INFO:server_backed_state_key_generator.cc(126)] Stable device secret missing!
2018-09-02T07:04:08.934163-07:00 INFO kernel: [  309.683245] tpm_tis tpm_tis: command 0xcc (size 146) returned code 0x0
2018-09-02T07:04:08.970169-07:00 INFO kernel: [  309.719132] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:09.008166-07:00 INFO kernel: [  309.757184] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:09.041161-07:00 INFO kernel: [  309.790159] tpm_tis tpm_tis: command 0x15 (size 14) returned code 0x0
2018-09-02T07:04:09.077174-07:00 INFO kernel: [  309.826155] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:09.132246-07:00 INFO kernel: [  309.881186] tpm_tis tpm_tis: command 0xb (size 36) returned code 0x0
2018-09-02T07:04:09.297159-07:00 INFO kernel: [  310.046125] tpm_tis tpm_tis: command 0xcc (size 146) returned code 0x0
2018-09-02T07:04:09.332428-07:00 INFO cryptohomed[724]: Lockbox created.
2018-09-02T07:04:09.333159-07:00 INFO kernel: [  310.082001] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:09.351111-07:00 INFO cryptohomed[724]: Attestation: Preparing for enrollment...
2018-09-02T07:04:09.377197-07:00 INFO kernel: [  310.126050] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:09.467162-07:00 INFO kernel: [  310.216750] tpm_tis tpm_tis: command 0x81 (size 59) returned code 0x0
2018-09-02T07:04:09.503157-07:00 INFO kernel: [  310.251950] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:09.530197-07:00 INFO kernel: [  310.279042] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:09.622194-07:00 INFO kernel: [  310.371715] tpm_tis tpm_tis: command 0x81 (size 59) returned code 0x0
2018-09-02T07:04:09.653179-07:00 INFO kernel: [  310.401900] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:09.653656-07:00 INFO cryptohomed[724]: Attestation: Creating identity 0 with identity feature(s) IDENTITY_FEATURE_ENTERPRISE_ENROLLMENT_ID.
2018-09-02T07:04:09.891179-07:00 INFO kernel: [  310.639929] tpm_tis tpm_tis: command 0xb (size 36) returned code 0x0
2018-09-02T07:04:09.918190-07:00 INFO kernel: [  310.666903] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:10.466154-07:00 INFO kernel: [  311.214622] tpm_tis tpm_tis: command 0x79 (size 187) returned code 0x0
2018-09-02T07:04:10.502178-07:00 INFO kernel: [  311.250596] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:10.541161-07:00 INFO kernel: [  311.287564] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:10.577173-07:00 INFO kernel: [  311.325627] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:10.607161-07:00 INFO kernel: [  311.355712] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-09-02T07:04:10.644180-07:00 INFO kernel: [  311.392630] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:10.681178-07:00 INFO kernel: [  311.429728] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-09-02T07:04:10.707221-07:00 INFO kernel: [  311.455617] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:10.804173-07:00 INFO kernel: [  311.552877] tpm_tis tpm_tis: command 0xcf (size 67) returned code 0x0
2018-09-02T07:04:10.834163-07:00 INFO kernel: [  311.582473] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:10.864164-07:00 INFO kernel: [  311.612522] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:10.906278-07:00 INFO kernel: [  311.654585] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-09-02T07:04:10.931164-07:00 INFO kernel: [  311.679482] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:11.022231-07:00 INFO kernel: [  311.770874] tpm_tis tpm_tis: command 0xcf (size 67) returned code 0x0
2018-09-02T07:04:11.052182-07:00 INFO kernel: [  311.800425] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:11.084197-07:00 INFO kernel: [  311.832472] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:11.114199-07:00 INFO kernel: [  311.862583] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-09-02T07:04:11.140229-07:00 INFO kernel: [  311.888449] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:11.232203-07:00 INFO kernel: [  311.980806] tpm_tis tpm_tis: command 0xcf (size 67) returned code 0x0
2018-09-02T07:04:11.268176-07:00 INFO kernel: [  312.016331] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:11.298216-07:00 INFO kernel: [  312.046384] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:11.334296-07:00 INFO kernel: [  312.082458] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-09-02T07:04:11.359160-07:00 INFO kernel: [  312.107348] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:11.455193-07:00 INFO kernel: [  312.203659] tpm_tis tpm_tis: command 0xcf (size 67) returned code 0x0
2018-09-02T07:04:11.491179-07:00 INFO kernel: [  312.239339] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:11.521201-07:00 INFO kernel: [  312.269348] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:11.557194-07:00 INFO kernel: [  312.305488] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-09-02T07:04:11.584879-07:00 INFO kernel: [  312.331268] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:11.685197-07:00 INFO kernel: [  312.433582] tpm_tis tpm_tis: command 0xcf (size 67) returned code 0x0
2018-09-02T07:04:11.729193-07:00 INFO kernel: [  312.477153] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:11.759178-07:00 INFO kernel: [  312.507245] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:11.789236-07:00 INFO kernel: [  312.537402] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-09-02T07:04:11.815225-07:00 INFO kernel: [  312.563242] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:11.905167-07:00 INFO kernel: [  312.653485] tpm_tis tpm_tis: command 0xcf (size 67) returned code 0x0
2018-09-02T07:04:11.948203-07:00 INFO kernel: [  312.696078] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:11.978178-07:00 INFO kernel: [  312.726177] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:12.008679-07:00 INFO kernel: [  312.756238] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-09-02T07:04:12.033201-07:00 INFO kernel: [  312.781120] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:12.126184-07:00 INFO kernel: [  312.874471] tpm_tis tpm_tis: command 0xcf (size 67) returned code 0x0
2018-09-02T07:04:12.156212-07:00 INFO kernel: [  312.904103] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:12.192193-07:00 INFO kernel: [  312.940064] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:12.228210-07:00 INFO kernel: [  312.976142] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-09-02T07:04:12.253219-07:00 INFO kernel: [  313.001028] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:12.357184-07:00 INFO kernel: [  313.105320] tpm_tis tpm_tis: command 0xcf (size 67) returned code 0x0
2018-09-02T07:04:12.393187-07:00 INFO kernel: [  313.140913] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:12.429169-07:00 INFO kernel: [  313.176945] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:12.465177-07:00 INFO kernel: [  313.213199] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-09-02T07:04:12.491239-07:00 INFO kernel: [  313.239000] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:12.589178-07:00 INFO kernel: [  313.337266] tpm_tis tpm_tis: command 0xcf (size 67) returned code 0x0
2018-09-02T07:04:12.619205-07:00 INFO kernel: [  313.366903] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:12.649184-07:00 INFO kernel: [  313.396907] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:12.679193-07:00 INFO kernel: [  313.427011] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-09-02T07:04:12.705228-07:00 INFO kernel: [  313.452920] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:12.803203-07:00 INFO kernel: [  313.551213] tpm_tis tpm_tis: command 0xcf (size 67) returned code 0x0
2018-09-02T07:04:12.833176-07:00 INFO kernel: [  313.580884] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:12.858483-07:00 INFO kernel: [  313.605802] tpm_tis tpm_tis: command 0x46 (size 14) returned code 0x0
2018-09-02T07:04:12.887163-07:00 INFO kernel: [  313.634802] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:12.947173-07:00 INFO kernel: [  313.694725] tpm_tis tpm_tis: command 0x65 (size 42) returned code 0x0
2018-09-02T07:04:13.729225-07:00 INFO kernel: [  314.476597] tpm_tis tpm_tis: command 0x41 (size 618) returned code 0x0
2018-09-02T07:04:13.759205-07:00 INFO kernel: [  314.506486] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:13.789187-07:00 INFO kernel: [  314.536456] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:14.043173-07:00 INFO kernel: [  314.791063] tpm_tis tpm_tis: command 0x16 (size 38) returned code 0x0
2018-09-02T07:04:14.074175-07:00 INFO kernel: [  314.821320] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x0
2018-09-02T07:04:14.100203-07:00 INFO kernel: [  314.847384] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:14.152176-07:00 INFO kernel: [  314.899294] tpm_tis tpm_tis: command 0x65 (size 42) returned code 0x0
2018-09-02T07:04:14.928203-07:00 INFO kernel: [  315.675179] tpm_tis tpm_tis: command 0x41 (size 618) returned code 0x0
2018-09-02T07:04:14.964207-07:00 INFO kernel: [  315.711041] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:14.994248-07:00 INFO kernel: [  315.741096] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:04:15.248298-07:00 INFO kernel: [  315.995646] tpm_tis tpm_tis: command 0x16 (size 38) returned code 0x0
2018-09-02T07:04:15.278668-07:00 INFO cryptohomed[724]: Attestation: Encrypting endorsement credential for the default PCA.
2018-09-02T07:04:15.279185-07:00 INFO kernel: [  316.025864] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x0
2018-09-02T07:04:15.304169-07:00 INFO kernel: [  316.050974] tpm_tis tpm_tis: command 0x46 (size 14) returned code 0x0
2018-09-02T07:04:15.329127-07:00 INFO cryptohomed[724]: Attestation: Encrypting endorsement credential for the test PCA.
2018-09-02T07:04:15.329264-07:00 INFO kernel: [  316.075937] tpm_tis tpm_tis: command 0x46 (size 14) returned code 0x0
2018-09-02T07:04:15.354179-07:00 INFO kernel: [  316.101034] tpm_tis tpm_tis: command 0x46 (size 14) returned code 0x0
2018-09-02T07:04:15.384198-07:00 INFO kernel: [  316.130952] tpm_tis tpm_tis: command 0x46 (size 14) returned code 0x0
2018-09-02T07:04:15.409176-07:00 INFO kernel: [  316.156163] tpm_tis tpm_tis: command 0x46 (size 14) returned code 0x0
2018-09-02T07:04:15.433197-07:00 INFO kernel: [  316.179919] tpm_tis tpm_tis: command 0x15 (size 14) returned code 0x0
2018-09-02T07:04:15.458208-07:00 INFO kernel: [  316.204962] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:15.555230-07:00 INFO kernel: [  316.301969] tpm_tis tpm_tis: command 0xd2 (size 68) returned code 0x0
2018-09-02T07:04:15.585210-07:00 INFO kernel: [  316.331825] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:15.609194-07:00 INFO kernel: [  316.355860] tpm_tis tpm_tis: command 0xdb (size 10) returned code 0x0
2018-09-02T07:04:15.665284-07:00 INFO kernel: [  316.411864] tpm_tis tpm_tis: command 0xb (size 36) returned code 0x0
2018-09-02T07:04:15.812204-07:00 INFO kernel: [  316.559180] tpm_tis tpm_tis: command 0xd5 (size 127) returned code 0x0
2018-09-02T07:04:15.842174-07:00 INFO kernel: [  316.588659] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:15.867203-07:00 INFO kernel: [  316.613777] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:15.957219-07:00 INFO kernel: [  316.703794] tpm_tis tpm_tis: command 0xd2 (size 68) returned code 0x0
2018-09-02T07:04:15.993169-07:00 INFO kernel: [  316.739600] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:16.023171-07:00 INFO kernel: [  316.769729] tpm_tis tpm_tis: command 0x46 (size 14) returned code 0x0
2018-09-02T07:04:16.049170-07:00 INFO kernel: [  316.795691] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:04:16.151202-07:00 INFO kernel: [  316.898374] tpm_tis tpm_tis: command 0x21 (size 59) returned code 0x0
2018-09-02T07:04:16.182201-07:00 INFO kernel: [  316.928590] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:16.212177-07:00 INFO kernel: [  316.958671] tpm_tis tpm_tis: command 0x15 (size 14) returned code 0x0
2018-09-02T07:04:16.268185-07:00 INFO kernel: [  317.014619] tpm_tis tpm_tis: command 0xb (size 36) returned code 0x0
2018-09-02T07:04:16.516242-07:00 INFO kernel: [  317.263223] tpm_tis tpm_tis: command 0x17 (size 163) returned code 0x0
2018-09-02T07:04:16.547252-07:00 INFO kernel: [  317.293458] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:04:16.571458-07:00 INFO kernel: [  317.317524] tpm_tis tpm_tis: command 0x46 (size 14) returned code 0x0
2018-09-02T07:04:16.601277-07:00 INFO cryptohomed[724]: Attestation: Prepared successfully (7250 ms).
2018-09-02T07:04:16.632185-07:00 INFO kernel: [  317.378515] tpm_tis tpm_tis: command 0x65 (size 18) returned code 0x0
2018-09-02T07:06:01.159207-07:00 INFO kernel: [  421.868017] tpm_tis tpm_tis: command 0xa (size 10) returned code 0x0
2018-09-02T07:06:01.255174-07:00 INFO kernel: [  421.964328] tpm_tis tpm_tis: command 0x21 (size 59) returned code 0x0
2018-09-02T07:06:01.291182-07:00 INFO kernel: [  421.999659] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x22
2018-09-02T07:06:01.329187-07:00 INFO kernel: [  422.037567] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
EOF

Comment 1 by derat@chromium.org, Sep 5

Cc: jrbarnette@chromium.org
Interestingly, chromeos4-row3-rack5-host1 appears to still be in a broken state days later. When I run tests on it now, they time out in the same place:

2018/09/05 06:21:04 [06:21:04.280] Waiting for cryptohome /home/user/ab69944031db568080af8635fbcf0c4d9e79fc0f
2018/09/05 06:21:57 [06:21:57.746] 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
   }
}
2018/09/05 06:21:57 [06:21:57.747] Error at chrome_login.go:69: Chrome login failed: /home/user/ab69944031db568080af8635fbcf0c4d9e79fc0f not mounted: context deadline exceeded

/sys/class/misc/tpm0/device/owned still contains 1.

The DUT had a "resetting" status in the Autotest DB. I've locked it so you can take a look, Andrey.

Please let me know if there's a condition (possibly involving can_decrypt, can_encrypt, and/or has_cryptohome_key?) that can be used to identify broken DUTs so they can be marked for repair.

Comment 3 by apronin@chromium.org, Sep 6

Cc: apronin@chromium.org
Owner: jclinton@chromium.org
Looks like the tests rely on the 1st login to trigger initializing the TPM. 
The TPM initialization starts if
a) Chrome explicitly tells cryptohomed to do it (usually as a part of OOBE when user clicks to EULA);
b) when the user logs in if not initialized yet [login is done using temporary software-based keys in thsi case].
That seems to explain the different 'owned' status for the two attempts (note: login failed at ~07:02, TPM init started at ~07:04).

Looking at the failed login attempt at 07:02: chrome log contains no attempts to actually login for ~2 minutes after showing the login screen:
[3313:3313:0902/070028.050738:VERBOSE1:webui_login_view.cc(608)] Login WebUI >> login-prompt-visible
[3313:3313:0902/070205.000436:VERBOSE1:component_updater_service.cc(107)] CrxUpdateService stopping

I do see repeated mosys crashes, and then 'stable device secret missing' (which is related iiuc: read vpd -> flashrom -> mosys).
I wonder if that's what prevents Chrome from starting the login (needs to read something from vpd -> flashrom -> mosys?):

2018-09-02T07:00:24.115258-07:00 WARNING crash_reporter[3270]: [user] Received crash notification for mosys[3269] sig 6, user 0 group 0 (developer build - not testing - always dumping)
...
2018-09-02T07:00:24.148062-07:00 WARNING mosys[3281]: libminijail[3281]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-09-02T07:00:24.148083-07:00 WARNING mosys[3281]: libminijail[3281]: compile_filter: compile_file() failed
2018-09-02T07:00:24.148099-07:00 ERR mosys[3281]: libminijail[3281]: failed to compile seccomp filter BPF program in '/usr/share/policy/mosys-seccomp.policy'
...
2018-09-02T07:00:28.092817-07:00 INFO session_manager[3298]: [INFO:server_backed_state_key_generator.cc(126)] Stable device secret missing!


That mosys failure seems to be a continuation of  issue 869971  and b/112037192 after putting mosys in minijail. 
rikku is x86_64/3.14, so probably that case went untested/unnoticed.

+jclinton: can you please take a look at this mosys crash and if it indeed ruins our logins on rikku?

Comment 4 by derat@chromium.org, Sep 6 

Thanks for looking at this, Andrey. That's interesting -- I saw the repeated mosys crashes but didn't realize that they might be part of the sequence that's broken here.

Can TPM initialization interfere with login in some cases, or is it expected to happen quickly and/or in the background? If it can interfere, and if there's an easy way for tests to trigger initialization themselves if it hasn't been completed or even started yet, I'd prefer to make it explicit at the start of these tests to reduce variability during login.

Comment 5 by apronin@chromium.org, Sep 6 

TPM init and login are supposed to be asynchronous.
There are certain points where they intersect: if TPM init has started but not completed yet (e.g. TPM owned, but later steps like PrepareForEnrollment still haven't started/finished), cryptohomed will use TPM-wrapped keys instead of s/w keys already. And given that the TPM init operations are often long, the user will see delays during login.

But in our case TPM initialization started already after the test timeout, on one of the later Chrome sessions:

1) The session is started by the test:
2018-09-02T07:00:24.500424-07:00 INFO session_manager[3298]: [INFO:browser_job.cc(148)] Running browser /opt/google/chrome/chrome --ppapi-flash-path=/opt/google/chrome/pepper/libpepflashplayer.so --ppapi-flash-version=31.0.0.108 --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=nss_cert_database_chromeos=1,*/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


2) Timeout, session killed:
2018-09-02T07:02:04.826189-07:00 INFO session_manager[3298]: [INFO:browser_job.cc(167)] Terminating browser process 3313 with signal 15: exiting cleanly

Note that TPM is not owned yet:
2018-09-02T07:02:05.163076-07:00 WARNING chapsd[694]: SRK does not exist - this is normal when the TPM is not yet owned.

Chrome restarts after the session is closed, and then is restarted again (I guess, by smth like 'restart ui' from the tests):
2018-09-02T07:02:05.915573-07:00 INFO session_manager[4685]: [INFO:browser_job.cc(148)] Running browser /opt/google/chrome/chrome [...]
2018-09-02T07:02:05.916940-07:00 INFO session_manager[4685]: [INFO:browser_job.cc(157)] Terminating process group for browser 4699 with signal 9: Restarting browser on-demand.

2018-09-02T07:02:05.917782-07:00 INFO session_manager[4685]: [INFO:browser_job.cc(148)] Running browser /opt/google/chrome/chrome --ppapi-flash-path=/opt/google/chrome/pepper/libpepflashplayer.so --ppapi-flash-version=31.0.0.108 --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 --remote-debugging-port=0 --disable-logging-redirect --ash-disable-system-sounds --oobe-skip-postlogin --disable-gaia-services --autoplay-policy=no-user-gesture-required --load-extension=/tmp/tast_chrome_extensions.588468377/test_api_extension --arc-availability=none --testing-channel=NamedTestingInterface:/tmp/.org.chromium.Chromium.L3Rx68/.org.chromium.Chromium.3IfO25 --vmodule=nss_cert_database_chromeos=1,*/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 --show-webui-login

Note that the flags are different this time: I havent' checked all, but at least, there're --show-webui-login, --oobe-skip-postlogin, --disable-gaia-services, which were not there for the session-under-test.

Looks like this time we show auto-enrollment screen.
[4700:4700:0902/070209.391942:VERBOSE1:wizard_controller.cc(823)] SkipToLoginForTesting.
[4700:4700:0902/070209.392390:VERBOSE1:auto_enrollment_controller.cc(539)] Auto-enrollment disabled: command line (gaia).
[4700:4700:0902/070209.392428:VERBOSE1:auto_enrollment_controller.cc(732)] New auto-enrollment state: 5
[4700:4700:0902/070209.392520:VERBOSE1:wizard_controller.cc(2038)] Showing enrollment screen. Forcing interactive enrollment: 0.
[4700:4700:0902/070209.392565:VERBOSE1:wizard_controller.cc(1333)] SetCurrentScreenSmooth: oauth-enrollment
[4700:4700:0902/070209.392906:VERBOSE1:gaia_screen_handler.cc(780)] HandleCompleteLogin


3) Then Chrome is restarted several more times (tests?), until eventually we get here to this session:

2018-09-02T07:04:05.271705-07:00 INFO session_manager[5454]: [INFO:browser_job.cc(148)] Running browser /opt/google/chrome/chrome --ppapi-flash-path=/opt/google/chrome/pepper/libpepflashplayer.so --ppapi-flash-version=31.0.0.108 --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 --remote-debugging-port=0 --disable-logging-redirect --ash-disable-system-sounds --oobe-skip-postlogin --disable-gaia-services --autoplay-policy=no-user-gesture-required --load-extension=/tmp/tast_chrome_extensions.037396019/test_api_extension --arc-availability=none --testing-channel=NamedTestingInterface:/tmp/.org.chromium.Chromium.HBVx2A/.org.chromium.Chromium.BhrVWG --vmodule=nss_cert_database_chromeos=1,*/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


Which does this (from chrome log):
[5472:5472:0902/070405.939880:WARNING:chrome_browser_main_chromeos.cc(484)] Request attempting TPM ownership.
I haven't seen this in previous chrome logs - at 07:00:24, 07:02:05, 07:04:03, 07:04:04.

It's coming from here:
https://cs.chromium.org/chromium/src/chrome/browser/chromeos/chrome_browser_main_chromeos.cc?q=chrome_browser_main_chromeos.cc&sq=package:chromium&dr&l=484
And assuming we run internal Chrome, not Chromium, that means one of the previous sessions emulated clicking through EULA, so TPM init was triggered at Chrome start.


TPM initialization indeed starts and succeeds:
2018-09-02T07:04:06.018832-07:00 INFO kernel: [  306.768902] tpm_tis tpm_tis: command 0x7c (size 30) returned code 0x0
...
2018-09-02T07:04:08.620210-07:00 ERR cryptohomed[724]: Taking TPM ownership took 2661ms        <--- so, it started ~07:04:05.96
2018-09-02T07:04:08.620446-07:00 INFO cryptohomed[724]: Configuring TPM, ownership taken: 1.
...
2018-09-02T07:04:09.351111-07:00 INFO cryptohomed[724]: Attestation: Preparing for enrollment...
...
2018-09-02T07:04:09.653656-07:00 INFO cryptohomed[724]: Attestation: Creating identity 0 with identity feature(s) IDENTITY_FEATURE_ENTERPRISE_ENROLLMENT_ID.
...
2018-09-02T07:04:15.278668-07:00 INFO cryptohomed[724]: Attestation: Encrypting endorsement credential for the default PCA.
...
2018-09-02T07:04:15.329127-07:00 INFO cryptohomed[724]: Attestation: Encrypting endorsement credential for the test PCA.
...
2018-09-02T07:04:16.601277-07:00 INFO cryptohomed[724]: Attestation: Prepared successfully (7250 ms).

Comment 6 by jclinton@chromium.org, Sep 10 

I'm just back from vacation today and it's unlikely that I'll be able to find time to look at this until the end of this week at the earliest.

Comment 7 by jclinton@chromium.org, Sep 13

Cc: jclinton@chromium.org
Owner: apronin@chromium.org
Looking at this briefly, I need a way to reproduce the mosys crash: what command is being run at the crash point? I don't see the command documented in Comment #3.

Comment 8 by apronin@chromium.org, Sep 21 

1) Re #7: I also don't know how mosys is invoked by Chrome. I suspect as a part of reading vpd data.
2) I now suspect that though mosys crash is real, it may be not the root cause of this issue here.

Looks like when ui.ChromeCrashLoggedIn starts, it assumes the device is already owned (TPM is owned/initialized). So, it starts a regular Chrome session, that only succeeds if we are past OOBE already. [Speculating here: need to verify that a "regular" telemetry session started by that test doesn't progress through sign-in, if still not owned.]

But if there were no previous tests on that DUT, it can (and _is_ in the example above) still be in OOBE. Note "owned": false reported before the test is run. [Question: it is expected that DUTs are in OOBE after repair? Seems so, unless something in the repair process initiates taking ownership and waits until it completes.]

Some later test starts Chrome session with "--show-webui-login, --oobe-skip-postlogin, --disable-gaia-services" (and may be other differences in options) and completes OOBE/owning the device. After that, signing-in works, and note "owned": true after the test.

@derat, does it look reasonable?

Comment 9 by derat@chromium.org, Sep 26

Cc: xiy...@chromium.org jdufault@chromium.org
Thanks for the analysis, Andrey.

I suspect that it's expected for DUTs to sometimes be in OOBE and/or to be unowned. Tast's login code initially matched (and still basically matches) Autotest/Telemetry's. I don't think I made any assumptions that weren't already there.

Tast passes --oobe-skip-postlogin and --disable-gaia-services but not --show-webui-login. That's definitely suspicious -- it was added by https://crrev.com/c/956311 as a fallback if Views-based login crashes ( issue 820212 ). The code to set it was recently removed by https://crrev.com/c/1232017 (see  issue 884454 ).

Xiyuan or Jacob, do you know if the code path triggered by Oobe.loginForTesting() has any expectations about the device's initial state with regard to having gone through OOBE and being owned?

Comment 10 by xiy...@chromium.org, Sep 26 

Login eventually does cryptohome business and TPM has to be owned. Usually TPM ownership is taken during Oobe Eula step [1]. It will be attempted again during chrome start up (what Andrey found), guarded by StartupUtils::IsEulaAccepted which is backed by prefs::kEulaAccepted in local state.

There might be a race though because I don't think login code would wait for TPM owning process to finish when it attempts cryptohome mount.

[1] https://cs.chromium.org/chromium/src/chrome/browser/chromeos/login/screens/eula_screen.cc?l=84

Comment 11 by apronin@chromium.org, Sep 27 

> It will be attempted again during chrome start up...

Just in case: It will also be attempted after a successful creation of a new user profile, if TPM is not initialized yet at that point.
https://cs.chromium.org/chromium/src/chrome/browser/chromeos/login/session/user_session_manager.cc?l=1158 -> ... ->
https://cs.chromium.org/chromium/src/chrome/browser/chromeos/login/session/user_session_manager.cc?l=1384

> There might be a race though because I don't think login code would wait for TPM owning process to finish when it attempts cryptohome mount.

Yes, login doesn't wait for TPM initialization - they are parallel processes. If TPM is not initialized yet by the time user logs in, software keys are temporarily used (and converted to TPM keys on the next login, when TPM is initialized).

Comment 12 by derat@chromium.org, Oct 9

Mergedinto: 875263
Status: Duplicate (was: Assigned)
I'm duping this into  issue 875263 , which is tracking more rikku login failures.
►

Sign in to add a comment