attached logs collected from guest user account.

Deleted: debug-logs_20170609-165823.tgz 2.5 MB

debug-logs_20170609-165823.tgz 2.5 MB Download

abodeti@ Is this only repro'able on Kevin or other devices too? Does this still repro on the latest 9642 build? If this is only Kevin this is not a dev blocker. Can you please confirm?

Ansar, if this is NOT a kevin only issue, please set the priority to 0 and assign to wzang@.

Logs indicate that cryptohome is failing authentication.

- Could you sign into any account, or did all of them fail?
- Did the device work again after reflashing?

The only UI related change I can think of that could affect this is caps lock; wzang@ can you confirm that caps lock is showing the indicator as expected?

I confirm caps lock is showing the indicator as expected. 

Reproduced only on kevin but not on peppy, minnie and caroline. 
attached latest logs.

Re#5 its failed to login all accounts.

Re#6 Caps lock if Off.

ChromeOS:9644.0.0/61.0.3128.0

Deleted: debug-logs_20170612-144858.tgz 8.2 MB

debug-logs_20170612-144858.tgz 8.2 MB Download

Over to Andrey since it looks like a cryptohome issue.

A few questions:
1) Was it the boot at ~16:24 on 06/09 when the login issues started (the screenshot is from 16:29)? 
2) Was it the first boot after AU?
3) What ChromeOS image version was it AU'ed from?

I do see the following errors that started happening on that boot:
2017-06-09T16:25:25.060468-07:00 ERR cryptohomed[1497]: Failed to set the encryption policy of /home/.shadow/30f82486827fe9ce141a22e027907b1007a02062/mount: Operation not supported
2017-06-09T16:25:25.060602-07:00 ERR cryptohomed[1497]: Failed to set directory encryption policy /home/.shadow/30f82486827fe9ce141a22e027907b1007a02062/mount

There were some login failures for a different username hash seen before that - at 14:45 we had an issue with cryptohome and chaps auth data:
2017-06-09T14:44:39.947881-07:00 ERR cryptohomed[1509]: TPM error 0x21 (Decryption error): Error calling Tspi_Data_Unbind
2017-06-09T14:44:39.948054-07:00 ERR cryptohomed[1509]: The TPM failed to unwrap the intermediate key with the supplied credentials
2017-06-09T14:44:39.948169-07:00 ERR cryptohomed[1509]: Failed to decrypt any keysets for b1a4d2b351adaf92540e5a73d350c7276fa1a0f5
2017-06-09T14:44:39.948411-07:00 WARNING cryptohomed[1509]: PKCS#11 initialization requested but cryptohome is not mounted.
2017-06-09T14:44:49.372563-07:00 ERR cryptohomed[1509]: Creating new salt at /home/root/b1a4d2b351adaf92540e5a73d350c7276fa1a0f5/chaps/auth_data_salt (0, 0)
2017-06-09T14:44:49.455198-07:00 INFO chapsd[1397]: Opening database in: /home/root/b1a4d2b351adaf92540e5a73d350c7276fa1a0f5/chaps
2017-06-09T14:44:49.471863-07:00 ERR chapsd[1397]: Old authorization data is not correct.
...
2017-06-09T14:44:50.028051-07:00 ERR cryptohomed[1509]: CHECKSUM: Checksum out-of-sync for /home/.shadow/b1a4d2b351adaf92540e5a73d350c7276fa1a0f5/master.0
...
2017-06-09T14:44:50.434626-07:00 WARNING cryptohomed[1509]: Unexpected user/group for /home/root/b1a4d2b351adaf92540e5a73d350c7276fa1a0f5/chaps/auth_data_salt.sum
2017-06-09T14:44:50.434942-07:00 WARNING cryptohomed[1509]: Unexpected permissions for /home/root/b1a4d2b351adaf92540e5a73d350c7276fa1a0f5/chaps/auth_data_salt.sum
2017-06-09T14:44:50.435009-07:00 WARNING cryptohomed[1509]: Unexpected permissions for /home/root/b1a4d2b351adaf92540e5a73d350c7276fa1a0f5/chaps/auth_data_salt

and earlier at 13:57:
2017-06-09T13:57:15.991603-07:00 ERR cryptohomed[1509]: DecryptFinal Error: 101077092: digital envelope routines, EVP_DecryptFinal_ex, bad decrypt
2017-06-09T13:57:16.324311-07:00 ERR cryptohomed[1509]: TPM error 0x21 (Decryption error): Error calling Tspi_Data_Unbind
2017-06-09T13:57:16.324515-07:00 ERR cryptohomed[1509]: The TPM failed to unwrap the intermediate key with the supplied credentials

If it was 9634.0.0 or later, I'd also suspect http://crrev.com/c/516805, which implements a new homedir key encryption approach, and migrates user's homedir to it on the first sign-in.

However, the issue described here started on 9633.0.0, before that CL landed. And I don't see "Migrating to deriving AES keys using scrypt", which marks migration to the new encryption approach, in the logs.

Still, if a 9634.0.0+ was at some point installed on the device, the user logged in, and later a pre-9634 image was installed, the user won't be able to login to his/hers homedir.

[Restoring. Removed from CC by accident.]

Comment #9 looks like an ext4 issue. Somehow ioctl(EXT4_IOC_SET_ENCRYPTION_POLICY) returned ENOTSUP (? - Operation not supported).

9632.0.0 contained a merge of Linux 4.4.70 into kernel-4.4 used on kevin.
Also, one of the separate kernel changes that landed in 9632.0.0 was Revert "FROMLIST: fscrypt: use 32 bytes of encrypted filename" (
https://chromium.googlesource.com/chromiumos/third_party/kernel/+/ec92ab9bcea598a11ba38e331c11018e46cfc3e7) with the comment that the underlying problem
has been fixed differently in the upstream kernel, and we are picking up
the upstream version with the merge.
Could it have caused it?

Gwendal, please take a look, if it's indeed an ext4 issue.
Assigning to you, if you don't mind. I'm away anyways in the near future.

For ioctl(EXT4_IOC_SET_ENCRYPTION_POLICY) returning ENOTSUP,
I've also seen it in one feedback and been digging into it (Bug 733969).

Merge of 4.4.70 introduced one ENOTSUP case to ioctl(EXT4_IOC_SET_ENCRYPTION_POLICY)--which I'm currently suspecting
https://chromium.googlesource.com/chromiumos/third_party/kernel/+/e2968fb8e7980dccc199dac2593ad476db20969f

#16: Question for me is if the referenced kernel commit introduces a bug (in other words, if it should be possible to call ioctl(EXT4_IOC_SET_ENCRYPTION_POLICY) if the underlying file system does not support encryption), or if it exposes a bug.

According to the upstream discussion https://lkml.org/lkml/2016/9/22/1152, some downstreams seem to be expecting it to work and still do the encryption when calling the ioctl without the feature flag set.

However, for ChromeOS, as far as I read the codebase, we should be flipping the feature flag on always when appropriate--hence, if we are really hitting the new check, that'll be an unexpected bug, I believe.

(disclaimer: I don't have any confidence at all whether the patch I mentioned in #16 is really the cause at the moment:))

is gwendal@ the right owner or should this be assigned to someone else? kinaba@? groeck@ ?

gwendal@ knows more about ext4 than me. We should check though if there is an underlying kernel bug or if the userspace change suggested in 733969 is the proper remedy. Question for me is if it is expected that journal playback can overwrite separately set feature flags (and that setting feature flags does not pass through the journal).

Journal replay overwriting the tune2fs modification should be an expected thing (as noted in the following commit message):
https://kernel.googlesource.com/pub/scm/fs/ext2/e2fsprogs/+/c5b3ae7fb5d58dd12a1e02c2443bad32c8a76150

What's not clear to me is whether it is an expected thing that the playback run by tune2fs itself overwriting the change... Anyway, even if there's any bug I think it's in tune2fs, not in the kernel.

For the severity of this issue,
if my suspect #16 is correct (and I'm inclined to believe so,)

> If this is only Kevin this is not a dev blocker.

The bug affects the devices with
* 4.4 kernel, and
* auto-updated from pre-ARC-N (either no ARC or ARC-M) to ARC-N

Wrote up a CL that fixed the issue for me at least:
https://chromium-review.googlesource.com/c/541176/

I'm not at all an expert in ext4 so I'd still like to wait for inputs from Gwendal.

Issue 733969 has been merged into this issue.

kinaba@ Is this affecting any other devices that are going through this migration?

4.4 kernel devices can be affected. (Clapper / Quawks?)

#13: the revert and install of the new patch for file is fine. Name of encrypted files can change across reboot we do not care.
#16: Returning EOPNOTSUPP at SET time is sane, the superblock (hence the filesystem are not ready).
At boot time, in ext4_dir_encryption_supported we use  EXT4_IOC_GET_ENCRYPTION_POLICY to check if it is sane to enable ext4. We will not do it if the kernel returns:
- ENOTTY: the ioctl is unknown or
- EOPNOTSUPP: ext4 crypto is not compiled in.
Otherwise we set the bit.

#21 seems to be root cause of the problem. It will happen if the filesystem is corrupted. cl/541176 sounds reasonable, I need to check where the cleaning was usually done.

Here are the list of devices that are 4.4 and getting N and possible ext4 migration on M61
- Kevin
- Clapper
- Quawks
- Reef
- Pyro
- Snappy 

I thought Reef/Pyro/Snappy were shipped with N from the beginning (i.e. no "migration").
Such ones should not be affected (except the early dogfooders.)

We have an early FSI for reef that forces the AU and there are also dogfooders which may be on M. The numbers are likely small but since the severity of this issue is safer to block these devices 

Sqauwks is also affected. Can you please no-go that too?

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform2/+/73e81e9e38ec6b26b0ec6c3f0bef6f1a6741dd47

commit 73e81e9e38ec6b26b0ec6c3f0bef6f1a6741dd47
Author: Kazuhiro Inaba <kinaba@chromium.org>
Date: Sat Jun 24 05:56:43 2017

init: Replay the journal before adding the ext4 encrypt feature.

The modification to the unmounted filesystem supernode by tune2fs
seems to be overwritten by journal replay in some cases. Make sure
that the revert does not happen.

BUG= chromium:731943 
BUG=chromium:733969
TEST=flash M59 Kevin; clobber-stateful; flash ToT Kevin; verify I can login.

Change-Id: I487db4fabed47901406ab66bcadc95deccb9da42
Reviewed-on: https://chromium-review.googlesource.com/541176
Commit-Ready: Kazuhiro Inaba <kinaba@chromium.org>
Tested-by: Kazuhiro Inaba <kinaba@chromium.org>
Reviewed-by: Gwendal Grignou <gwendal@chromium.org>
Reviewed-by: Mike Frysinger <vapier@chromium.org>

[modify] https://crrev.com/73e81e9e38ec6b26b0ec6c3f0bef6f1a6741dd47/init/chromeos_startup

I'm seeing this same behavior for caroline on M60.  See feedback report 72067836447

At least for the particular report 72067836447, it does not look to be the same bug as this one.

In this bug, we "Failed to set the encryption policy" by ENOTSUPP, while the report is dying with EINVAL,
for some reason with "ext4_process_policy: Policy inconsistent with encryption context".
It reminds me of b/38097492 "Inconsistent encryption contexts" slightly, but the point of failure is different.

# By the way, why's Caroline migrating?


[1433:1433:0831/184757.429287:VERBOSE1:cryptohome_authenticator.cc(752)] Resolved state to: 0
[1433:1433:0831/184757.878465:ERROR:device_event_log_impl.cc(156)] [18:47:57.878] Login: homedir_methods.cc:414 HomedirMethods MountEx error (CryptohomeErrorCode): 30
[1433:1433:0831/184757.878503:ERROR:device_event_log_impl.cc(156)] [18:47:57.878] Login: cryptohome_authenticator.cc:909 Cryptohome failure: state(AuthState)=25, code(cryptohom<IPv6: 1>MountError)=256
[1433:1433:0831/184757.878515:VERBOSE1:cryptohome_authenticator.cc(752)] Resolved state to: 25
[1433:1433:0831/184757.878548:VERBOSE1:login_display_host_impl.cc(623)] Login WebUI >> wizard
[1433:1433:0831/184757.878614:VERBOSE1:wizard_controller.cc(281)] Starting OOBE wizard with screen: encryption-migration
[1433:1433:0831/184757.883255:VERBOSE1:wizard_controller.cc(638)] Showing encryption migration screen.
[1433:1433:0831/184757.886072:INFO:signin_screen_handler.cc(1447)] Login WebUI >> active: 0, source: gaia-signin
[1433:1433:0831/184758.434079:ERROR:device_event_log_impl.cc(156)] [18:47:58.434] Login: homedir_methods.cc:414 HomedirMethods MountEx error (CryptohomeErrorCode): 5



2017-08-31T18:47:57.878049-04:00 INFO cryptohomed[1751]: Mount failed because both ecryptfs and dircrypto home directory is found. Need to resume and finish migration first.
2017-08-31T18:47:57.878177-04:00 WARNING cryptohomed[1751]: PKCS#11 initialization requested but cryptohome is not mounted.
2017-08-31T18:47:58.294978-04:00 DEBUG kernel: [   58.439875] SELinux: initialized (dev ecryptfs, type ecryptfs), uses xattr
2017-08-31T18:47:58.294992-04:00 WARNING kernel: [   58.439922] ext4_process_policy: Policy inconsistent with encryption context
2017-08-31T18:47:58.294909-04:00 ERR cryptohomed[1751]: Failed to set the encryption policy of /home/.shadow/1cc1bcca58c429fbcc8fe856fc0b702b373fd415/mount: Invalid argument
2017-08-31T18:47:58.294932-04:00 ERR cryptohomed[1751]: Failed to set directory encryption policy /home/.shadow/1cc1bcca58c429fbcc8fe856fc0b702b373fd415/mount
2017-08-31T18:47:58.398836-04:00 INFO kernel: [   58.543223] MountThread (2242): drop_caches: 3
2017-08-31T18:47:58.415835-04:00 INFO kernel: [   58.560648] MountThread (2242): drop_caches: 3
2017-08-31T18:47:58.433766-04:00 WARNING cryptohomed[1751]: PKCS#11 initialization requested but cryptohome is not mounted.

Link to 760007: AU triggered the bug described here.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform2/+/920c7f55dfcb4c0051c9391474e0c33878177c9e

commit 920c7f55dfcb4c0051c9391474e0c33878177c9e
Author: Kazuhiro Inaba <kinaba@chromium.org>
Date: Wed Sep 13 16:20:52 2017

init: Replay the journal before adding the ext4 encrypt feature.

The modification to the unmounted filesystem supernode by tune2fs
seems to be overwritten by journal replay in some cases. Make sure
that the revert does not happen.

BUG= chromium:731943 
BUG=chromium:733969
TEST=flash M59 Kevin; clobber-stateful; flash ToT Kevin; verify I can login.

Change-Id: I487db4fabed47901406ab66bcadc95deccb9da42
Reviewed-on: https://chromium-review.googlesource.com/541176
Commit-Ready: Kazuhiro Inaba <kinaba@chromium.org>
Tested-by: Kazuhiro Inaba <kinaba@chromium.org>
Reviewed-by: Gwendal Grignou <gwendal@chromium.org>
Reviewed-by: Mike Frysinger <vapier@chromium.org>
(cherry picked from commit 73e81e9e38ec6b26b0ec6c3f0bef6f1a6741dd47)
Reviewed-on: https://chromium-review.googlesource.com/665337
Commit-Queue: Gwendal Grignou <gwendal@chromium.org>
Tested-by: Gwendal Grignou <gwendal@chromium.org>

[modify] https://crrev.com/920c7f55dfcb4c0051c9391474e0c33878177c9e/init/chromeos_startup