+apronin for cryptohomed/tpm expertise

Interesting log lines:

Probably start from a new device state:
====
2017-03-24T00:18:04.664810+00:00 INFO cryptohomed[1664]: TPM error 0x2020 (Key not found in persistent storage): LoadKeyByUuid: failed LoadKeyByUUID
2017-03-24T00:18:04.783565+00:00 ERR cryptohomed[1664]: Couldn't wrap cryptohome key
...
2017-03-24T00:18:04.876734+00:00 INFO cryptohomed[1664]: TPM error 0x2020 (Key not found in persistent storage): Unseal: Failed to load SRK.
2017-03-24T00:18:04.877080+00:00 ERR cryptohomed[1664]: Cannot unseal aes key.
2017-03-24T00:18:04.877121+00:00 ERR cryptohomed[1664]: Attestation: Could not unseal decryption key.
...

TPM initialized, and device enrolled
=====
2017-03-24T00:18:24.700461+00:00 ERR cryptohomed[1664]: TPM initialization took 2822ms
2017-03-24T00:18:24.700559+00:00 INFO cryptohomed[1664]: Finalizing TPM initialization, ownership taken: 1.
...
2017-03-24T00:18:25.397963+00:00 INFO cryptohomed[1664]: Lockbox created.
...
2017-03-24T00:18:25.470005+00:00 WARNING cryptohomed[1664]: Attestation: Using default PCA. Alternate PCA will not be available.
2017-03-24T00:18:25.470023+00:00 INFO cryptohomed[1664]: Attestation: Preparing for enrollment...
...
2017-03-24T00:18:34.720879+00:00 INFO cryptohomed[1664]: Attestation: Prepared successfully (8535ms).
...2017-03-24T00:21:39.745170+00:00 INFO cryptohomed[1664]: Encrypted partition finalized.
2017-03-24T00:21:39.786131+00:00 INFO cryptohomed[1664]: InstallAttributes have been finalized.
...
2017-03-24T00:21:54.425392+00:00 INFO cryptohomed[1664]: TPM error 0x2020 (Key not found in persistent storage): LoadKeyByUuid: failed LoadKeyByUUID
...
2017-03-24T00:21:54.910185+00:00 INFO cryptohomed[1664]: Created new cryptohome key.

Then A few success user logins:
====
2017-03-24T00:21:57.904064+00:00 INFO cryptohomed[1664]: Migrated (or created) user directory: /home/.shadow/20c9c19ab4319c104d667fdbba512189066dcfcc/vault
...
2017-03-24T00:22:33.338158+00:00 INFO cryptohomed[1664]: Migrated (or created) user directory: /home/.shadow/bb994330609bd7e86e7134fe6b21f39f7932dee9/vault
...
2017-03-24T00:24:04.767999+00:00 INFO cryptohomed[1664]: Migrated (or created) user directory: /home/.shadow/bb994330609bd7e86e7134fe6b21f39f7932dee9/vault
...
2017-03-24T00:24:49.322451+00:00 INFO cryptohomed[1664]: Migrated (or created) user directory: /home/.shadow/b6e4684d3e816d3c17e7e35f0ca1d571a3e0c3c7/vault

Problem starts to happen, unable to decrypt. 
====
2017-03-24T00:26:26.195088+00:00 ERR cryptohomed[1664]: TPM error 0x21 (Decryption error): Error calling Tspi_Data_Unbind
2017-03-24T00:26:26.195341+00:00 ERR cryptohomed[1664]: The TPM failed to unwrap the intermediate key with the supplied credentials
2017-03-24T00:26:26.195710+00:00 INFO kernel: [  505.628263] tpm_tis tpm_tis: command 0x1e (size 274) returned code 0x21
2017-03-24T00:26:26.195661+00:00 ERR cryptohomed[1664]: Failed to decrypt any keysets for bb994330609bd7e86e7134fe6b21f39f7932dee9
2017-03-24T00:26:26.196121+00:00 WARNING cryptohomed[1664]: PKCS#11 initialization requested but cryptohome is not mounted.
...
2017-03-24T00:27:15.850058+00:00 ERR cryptohomed[1664]: TPM error 0x21 (Decryption error): Error calling Tspi_Data_Unbind
..

Chrome should be trying to nuke everything and re-create cryptohome, cotinues to fail, but with a different tpm error now
====
2017-03-24T00:27:24.009737+00:00 ERR cryptohomed[1664]: TPM error 0x1 (Authentication failed): Error calling Tspi_Key_GetPubKey
2017-03-24T00:27:24.009796+00:00 ERR cryptohomed[1664]: Unable to get the cryptohome public key from the TPM.
2017-03-24T00:27:24.009840+00:00 ERR cryptohomed[1664]: TPM public key hash mismatch.
...
This repeats a few times, probably chrome keeps trying it...

Device stays in that state afterwards. Reboot seems resolved the issue.

Re #1. Trying to make sense of the log, but nothing obvious so far.

1) In fact, we have logged in with user #2 (bb994330609bd7e86e7134fe6b21f39f7932dee9) just fine.
Then closed the session and immediately logged in with user #1 (b6e4684d3e816d3c17e7e35f0ca1d571a3e0c3c7). No issues.
And then we are trying to mount the home for the 2nd user (bb994330609bd7e86e7134fe6b21f39f7932dee9). The keyset is there but we fail to decrypt it with the provided credentials. No TPM errors between the previous successful login and this unsuccessful attempt. It's not a lckout or communication issue - the error is clear: we fail to decrypt.

It could have been explained by using wrong credentials. But right after that the session (with both users #1 and #2) is closed, and we start a new one, with user #2 only, and fail to use the credentials again (same error). Note that this time the session for the 1st user is closed. So, it's not just repeated attempts to add a user to the session. It's starting a new session with that 2nd user. It's unlikely wrong credentials are used this time...

The keyset is never re-encrypted with the new authkey as result of these errors. Which is confirmed by the ability to login after reboot.

After rebooting we succeeded when adding users to the session in the reverse order - first user #2, then user #1. I wonder, if the order matters here. When mounting cryptohomes, the keysets are scanned until the first one with a matching label is found. Or any one is found, if an empty label is provided. If several matching keysets exist, once we get an error for the first matching keyset, we don't attempt the others. 

Is it possible that there are two authkeys for user #2? (E.g. as a result of not clearing the disk when the TPM owner was cleared and leaving there old keysets?) 
And when we login, we specify some non-empty label which matches the second keyset, and it works fine with the credentials (since it matches the current cryptohome key).
When we add a user to the session, we specify an empty label, and thus an old keyset is picked up (which assumes some old cryptohome). And it doesn't work, although the password is correct.

2) There're actually three users on the device, not two - is that right?
And what I also don't quite understand is why we created the cryptohome for user #2 twice. That might be related to having two keysets for user #2:
2017-03-24T00:21:57.904064+00:00 INFO cryptohomed[1664]: Migrated (or created) user directory: /home/.shadow/20c9c19ab4319c104d667fdbba512189066dcfcc/vault
2017-03-24T00:22:33.338158+00:00 INFO cryptohomed[1664]: Migrated (or created) user directory: /home/.shadow/bb994330609bd7e86e7134fe6b21f39f7932dee9/vault
2017-03-24T00:24:04.767999+00:00 INFO cryptohomed[1664]: Migrated (or created) user directory: /home/.shadow/bb994330609bd7e86e7134fe6b21f39f7932dee9/vault
2017-03-24T00:24:49.322451+00:00 INFO cryptohomed[1664]: Migrated (or created) user directory: /home/.shadow/b6e4684d3e816d3c17e7e35f0ca1d571a3e0c3c7/vault

3) I also don't get the authorization errors when trying to access the public part of cryptohome key. Another explanation to all that could be that we loaded a wrong cryptohome key (so, decrypt and all accesses to it fail) due to some disk or memory glitch, or we somehow have a wrong cryptohome key handle. Or someone silently unloaded one cryptohome kye and loaded a different ones. But I don't see any lines that could hint that in the log.

Bottomline: would be interesting to see if it's possible to reproduce the issue (e.g. by adding users to the session in a different order). If so, then check what's happening with the system in such case on a test image with extra debug. So far, no good clues.

Thanks for the investigation and detailed observation!

Re#2: I was testing some issue related to login screen, so I might have added one account and deleted it in the middle. And that's the reason I kept signing in and signing out. But when this issue popped out, I only have two accounts on the device, not 3 accounts.

Unfortunately, I could not repro this case after rebooting, no matter in which order I log in the accounts. I'll update this thread if I can encounter this issue again in the future.

Daisy, can we close this bug since we can't reproduce?

I haven't seen this bug for a long time. Close it.