Logs: https://pantheon.corp.google.com/storage/browser/chromiumos-test-logs/bugfiles/cr/690710/

this issue also happens on Elm and Minnie updates from 9202.22.0 to 9202.25.0 beta.

reproduced on all devices.

abodenha@ who could look at startscreen issues do you think?

This is actually a Chrome bug related to trying to load settings data.

steel@ can someone on your team take a look?

Jacob, could you take a look?

There are tons of cryptohome errors in the logs; I'm guessing something broke there.

Owner to apronin@ who has made most of the cryptohome changes lately + cc on other recent committers.

example log statements:  

[1126:1126:0209/152139.285038:ERROR:device_event_log_impl.cc(140)] [15:21:39.284] Login: homedir_methods.cc:402 HomedirMethods MountEx error: 1
- error = CRYPTOHOME_ERROR_ACCOUNT_NOT_FOUND

[1126:1126:0209/152139.285160:ERROR:device_event_log_impl.cc(140)] [15:21:39.285] Login: cryptohome_authenticator.cc:886 Cryptohome failure: state=1, code=32
- state = NO_MOUNT
- code = MOUNT_ERROR_USER_DOES_NOT_EXIST

a bit more from messages:

2017-02-09T23:20:16.358723+00:00 ERR shill[1186]: [ERROR:crypto_des_cbc.cc(103)] Unable to load key matter from /var/lib/whitelist/owner.key
2017-02-09T23:20:16.383735+00:00 ERR shill[1186]: [ERROR:crypto_des_cbc.cc(103)] Unable to load key matter from /var/lib/whitelist/owner.key
2017-02-09T23:20:16.384145+00:00 ERR shill[1186]: [ERROR:crypto_des_cbc.cc(103)] Unable to load key matter from /var/lib/whitelist/owner.key
2017-02-09T23:20:16.439724+00:00 NOTICE cros-machine-id-regen[1220]: Regenerated /var/lib/dbus/machine-id (reason: network).
2017-02-09T23:20:17.820028+00:00 INFO kernel: [    5.829281] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2017-02-09T23:20:17.850023+00:00 INFO kernel: [    5.859221] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2017-02-09T23:20:17.867886+00:00 INFO cryptohomed[1302]: TPM error 0x2020 (Key not found in persistent storage): LoadKeyByUuid: failed LoadKeyByUUID
2017-02-09T23:20:18.120171+00:00 ERR cryptohomed[1302]: Couldn't wrap cryptohome key
2017-02-09T23:20:18.120375+00:00 WARNING cryptohomed[1302]: Could not load the device policy file.
2017-02-09T23:20:18.120613+00:00 ERR cryptohomed[1302]: Creating new salt at /home/.shadow/salt (0, 0)
2017-02-09T23:20:18.140264+00:00 WARNING chapsd[1131]: SRK does not exist - this is normal when the TPM is not yet owned.
2017-02-09T23:20:18.140754+00:00 WARNING chapsd[1131]: SRK does not exist - this is normal when the TPM is not yet owned.
2017-02-09T23:20:18.140973+00:00 WARNING cryptohomed[1302]: Attestation-based enterprise enrollment will not be available.
2017-02-09T23:20:18.166405+00:00 WARNING cryptohomed[1302]: Extending PCR1.
2017-02-09T23:20:18.167213+00:00 INFO kernel: [    6.176218] tpm_tis tpm_tis: command 0x15 (size 14) returned code 0x0
2017-02-09T23:20:18.210423+00:00 ERR cryptohomed[1302]: stat() of /mnt/stateful_partition/unencrypted/preserve/attestation.epb failed.: No such file or directory
2017-02-09T23:20:18.210474+00:00 ERR cryptohomed[1302]: Failed to read db: No such file or directory
2017-02-09T23:20:18.210483+00:00 INFO cryptohomed[1302]: Attestation: Attestation data not found.
2017-02-09T23:20:18.211024+00:00 INFO kernel: [    6.220217] tpm_tis tpm_tis: command 0x14 (size 34) returned code 0x0
2017-02-09T23:20:18.237922+00:00 INFO kernel: [    6.245319] tpm_tis tpm_tis: command 0x46 (size 14) returned code 0x0
2017-02-09T23:20:18.297034+00:00 INFO kernel: [    6.306768] tpm_tis tpm_tis: command 0x7c (size 30) returned code 0x0
2017-02-09T23:20:18.297110+00:00 INFO cryptohomed[1302]: Cannot read boot lockbox files.
2017-02-09T23:20:18.337030+00:00 INFO kernel: [    6.346170] tpm_tis tpm_tis: command 0x65 (size 20) returned code 0x0
2017-02-09T23:20:18.373029+00:00 INFO kernel: [    6.382210] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2017-02-09T23:20:18.409043+00:00 INFO kernel: [    6.418413] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0

Re #10 those lines in the log are normal on a clean machine as a part of initialization.

I looked through the logs.

1) First boot on 02/09 at 15:20:13. TPM is not owned.

2) Successfully complete TPM initialization:
2017-02-09T23:20:58.313768+00:00 ERR cryptohomed[1302]: TPM initialization took 3182ms
2017-02-09T23:21:06.943479+00:00 INFO cryptohomed[1302]: Attestation: Prepared successfully (7910ms).
2017-02-09T23:21:41.107274+00:00 INFO cryptohomed[1302]: InstallAttributes have been finalized.
2017-02-09T23:21:41.587223+00:00 INFO cryptohomed[1302]: Created new cryptohome key.

3) Login. Created user directory:
2017-02-09T23:23:13.087341+00:00 INFO cryptohomed[1302]: Migrated (or created) user directory: /home/.shadow/2a27e1e90fe3c10b0f8d9a6f1c46dacdf6523f60/vault
...
2017-02-09T23:23:13.182153+00:00 INFO cryptohomed[1302]: PKCS#11 initialization succeeded.
2017-02-09T23:23:13.186779+00:00 INFO chapsd[1131]: Initializing key hierarchy for token at /home/root/2a27e1e90fe3c10b0f8d9a6f1c46dacdf6523f60/chaps

4) Logout:
2017-02-09T23:24:41.347542+00:00 INFO session_manager[5170]: [INFO:session_manager_impl.cc(463)] Stopping all sessions
2017-02-09T23:24:41.347619+00:00 INFO session_manager[5170]: [INFO:browser_job.cc(157)] Terminating process: 
...
2017-02-09T23:24:43.752174+00:00 INFO session_manager[5170]: [INFO:policy_service.cc(202)] Persisted policy to disk.
2017-02-09T23:24:43.770693+00:00 WARNING kernel: [  271.923123] init: debugd main process (5217) killed by TERM signal
2017-02-09T23:24:43.758620+00:00 INFO session_manager[5170]: [INFO:policy_service.cc(202)] Persisted policy to disk.
2017-02-09T23:24:43.808150+00:00 INFO chapsd[1131]: Token at /home/root/2a27e1e90fe3c10b0f8d9a6f1c46dacdf6523f60/chaps has been removed from slot 1
2017-02-09T23:24:43.843841+00:00 INFO chapsd[1131]: Unloaded keys for slot 1

5) Login again?
2017-02-09T23:24:44.001846+00:00 INFO session_manager[6736]: [INFO:session_manager_service.cc(167)] SessionManagerService starting

Here we see a problem mounting the user homedir?:
2017-02-09T23:24:52.482908+00:00 ERR cryptohomed[1302]: TPM error 0x21 (Decryption error): Error calling Tspi_Data_Unbind
2017-02-09T23:24:52.482963+00:00 ERR cryptohomed[1302]: The TPM failed to unwrap the intermediate key with the supplied credentials
2017-02-09T23:24:52.482994+00:00 ERR cryptohomed[1302]: Failed to decrypt any keysets for 2a27e1e90fe3c10b0f8d9a6f1c46dacdf6523f60
2017-02-09T23:24:52.483072+00:00 WARNING cryptohomed[1302]: PKCS#11 initialization requested but cryptohome is not mounted.
...
2017-02-09T23:24:59.854797+00:00 WARNING session_manager[6736]: [WARNING:user_policy_service_factory.cc(88)] Failed to load user policy data, continuing anyway.
2017-02-09T23:24:59.858158+00:00 WARNING session_manager[6736]: [WARNING:device_policy_service.cc(414)] Could not verify that owner key belongs to this user.
2017-02-09T23:24:59.906084+00:00 INFO session_manager[6736]: [INFO:session_manager_impl.cc(438)] Starting user session

Though eventually:
2017-02-09T23:25:00.531239+00:00 WARNING cryptohomed[1302]: message repeated 2 times: [ GetTpmTokenSlotForPath: Path not found.]
2017-02-09T23:25:00.647707+00:00 WARNING cryptohomed[1302]: RemoveKeyset: key to remove not found
2017-02-09T23:25:00.650082+00:00 INFO chapsd[1131]: Opening database in: /home/root/2a27e1e90fe3c10b0f8d9a6f1c46dacdf6523f60/chaps
2017-02-09T23:25:00.677056+00:00 INFO chapsd[1131]: Slot 1 ready for token at /home/root/2a27e1e90fe3c10b0f8d9a6f1c46dacdf6523f60/chaps
2017-02-09T23:25:00.677700+00:00 INFO cryptohomed[1302]: A Pkcs11_Init event got finished.
2017-02-09T23:25:00.677769+00:00 INFO cryptohomed[1302]: PKCS#11 initialization succeeded.

6) Then reboot, and everything looks normal. Though no logins.

Could you please elaborate on what was going on? Was there a login and then logout?
As the machine supposed to be unowned? Otherwise, the actual problem might be that the ownership was cleared. But why - that is not captured in the logs generated after re-taking ownership. Old encrypted stateful with /var/log/messages is lost.

Hmm, and I also don't see any changes in cryptohome/chaps tpm-related daemons between 9202.18.0 and 9202.21.0 or 9202.22.0 and 9202.25.0, or for that matter between 9202.18.0 and 9202.25.0 that could cause something like that.

Here is the list for platform2 for 9202.18.0..9202.25.0:
https://chromium.googlesource.com/chromiumos/platform2/+log/4c9fb5635250b8901a53bfbda8ae089f47834951..914f0457742295402df8d4f38df3c533e67d5392?n=10000

This one doesn't change the code that runs for tpm 1.2 chips at all:
https://chromium.googlesource.com/chromiumos/platform2/+/7da3b1c592bd90f377693df3f3f38bf3ba18ec7e

This one adds a flag to common tpm 2.0/tpm 1.2 header (ignored for tpm 1.2) and sets this flag for FWMP space (most probably does not exist on those devices; in any case ignored for tpm 1.2):
https://chromium.googlesource.com/chromiumos/platform2/+/914f0457742295402df8d4f38df3c533e67d5392

All other changes are in tpm 2.0 code, which doesn't run on elm, minnie or peppy.
So, I'm puzzled. Or, we are just looking in the wrong place with cryptohome. 

Is this problem only seen after 9202.18.0? Am I right it's not seen on ToT? Re #4 about being reproducible on all devices - what build were they on, if it was AU - from what build?

This is the most suspicious change (that file in particular in that CL) among all made in 9202.x.0 series: https://chromium-review.googlesource.com/#/c/436624/2/cryptohome/crypto.cc
But it landed in 9202.14.0 already.

sdantuluri@ does this happen consistently?

ketakid@ Issue reproduced consistently.

AU from public beta build (9202.18.0 / 57.0.2987.32) to today's beta (9202.28.0 / 57.0.2987.54)

Tested on peppy, quawks

Attached device logs from peppy. (AU from 9202.18.0 to 9202.28.0)

1. Logs taken right after AU without logging in to any user account
2. Logs taken after logging into owner user account.

https://pantheon.corp.google.com/storage/browser/chromiumos-test-logs/bugfiles/cr/690710/

Well, in Chrome logs I see the following errors
[1180:1475:0209/152754.928645:WARNING:web_database.cc(111)] Web database is too new.

Which means that this constant in web_database.cc is lower than what's in the actual database: https://cs.corp.google.com/clankium/src/components/webdata/common/web_database.cc?q=web_database.cc&dr&l=16

I looked at the changes on the Chrome side made between .18 and .21, i.e. between 57.0.2987.32 and 57.0.2987.35.

I see this revert: https://codereview.chromium.org/2679803002 It indeed sends the version back from 71 to 70 (here: https://codereview.chromium.org/2679803002/patch/1/10013). So, what's reported in that error box on the screen is true.

Who should I assign it to on the Chrome side?

BTW, for the future: is there a good way to imitate what AU does with upgrading the image w/o actually going through AU? Is "chromeos-install --preserve_stateful" a good approximation?

sdantuluri@ Does this issue exist on the Beta that is out there? .18?

ketakid@ No. Haven't seen this issue with .18

If I read the changelogs correctly:
 
The original change (https://codereview.chromium.org/2676723004) that incremented the web_database version to 71 was picked in Chrome 57.0.2987.27, so made it to Chrome OS 9202.16.0. 

Then it was reverted (https://codereview.chromium.org/2679803002) in Chrome 57.0.2987.35 => Chrome OS 9202.20.0. That reverted the web_database version back to 70.

So, if somebody installed a version between .16 and .19 (e.g. .18 as in our case), and later upgraded to .20 or later, that user should see that error.

re #22: That's what I see as well. The profile corruption happens if chrome updates from (57.0.2987.27 - 57.0.2987.35) into a version between (57.0.2987.35 - 58.0.2993.0).

Assuming that the number of users with Chrome (57.0.2987.27 - 57.0.2987.35) is small, I recommend that we close this issue.

Assigning to ketakid to either close as WontFix or reassign to sebsb@ to merge a patch that fixes corruption/bad revert for the affect version range.

Initial: https://chromium.googlesource.com/chromium/src/+/542707dcc5ebccf4683dbf24cb27f148b5e7d824
Revert: https://chromium.googlesource.com/chromium/src/+/a2ccc8a90d093dcaeea01c122fe6dbcb62920674
Reland: https://chromium.googlesource.com/chromium/src/+/3e77d95a76768a00bfb8cffc4799b52e640c1ae7

Hi,

The comments #22-23 seem accurate to me except on one small detail. 

The initial patch was created for M-58 https://chromium.googlesource.com/chromium/src/+/3e77d95a76768a00bfb8cffc4799b52e640c1ae7

I then merged it to M-57 https://chromium.googlesource.com/chromium/src/+/542707dcc5ebccf4683dbf24cb27f148b5e7d824

Which I then reverted https://chromium.googlesource.com/chromium/src/+/a2ccc8a90d093dcaeea01c122fe6dbcb62920674

So It should not be a problem anymore, only those who had the code between the merge and the merge-revert should be affected. 

ketakid@ WDYT? is a patch needed or is this a WontFix?

Can sdantuluri@ confirm this hypothesis? If yes, we should close this as won't fix.

Tested AU on samus from 9000.80.0 beta to 9202.28.0 beta. Not seeing profile error.

But doesn't "only those who had the code change between the merge and the merge-revert" mean everybody currently on Beta? 

jdufault@ ? can you comment on this?

ketakid@, can you determine roughly how many people updated to a version between (57.0.2987.27 - 57.0.2987.35)?

If it is not that large, I would mark as WontFix.

If it is a very large number of users, I still think a WontFix could be reasonable, since it is beta and not stable. Though we may want to consider patching a fix; but it could get messy :(

Song & I were able to see this Profile error today when the devices are auto-updated from M56 [56.0.2924.79] --> M57 [57.0.2987.54] on Daisy & Candy devices.

jdufault@ Beta is at 100% so at least a couple thousand machines. I would still fix it on Beta but take it on the next beta. dhaddock@/vsuley@ let us fix this bug for beta 3.

mini branch 2987_54 created, please merge fix to branch 2987_54. To trigger a mini branch build, please use branch number: 2897_54 in the trigger app.

Profile error not seen on 9202.28.1, 57.0.2987.59

Tested Daisy, Peppy, Quawks : AU from (9202.18.0 / 57.0.2987.32) ==> 9202.28.1, 57.0.2987.59

[Auto-generated comment by a script] We noticed that this issue is targeted for M-57; it appears the fix may have landed after branch point, meaning a merge might be required. Please confirm if a merge is required here - if so add Merge-Request-57 label, otherwise remove Merge-TBD label. Thanks.