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

Issue 378338 link

Starred by 12 users

Unable to create a supervised user as some "TPM error" message is shown.

Project Member Reported by ysriniva...@mahindrasatyam.com, May 28 2014

Issue description

UserAgent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2017.2 Safari/537.36
Platform: 5898.0.0 dev-channel daisy,peppy

Steps to reproduce the problem:
1.Create a new user1 and sign in to that user. 
2.Now sign out of user1 and try to create a Supervised user for it.

What is the expected behavior?
Should be able create a supervised user.

What went wrong?
some error message like "Oops, TPM error" asking for reboot the device, is shown while trying to create a supervised user.

Did this work before? Yes 

Chrome version: 37.0.2017.2  Channel: dev
OS Version: 37.0.2017.2
Flash Version: Shockwave Flash 14.0 r0

This is a regression issue as it is working fine in M35:35.0.1916.99/5712.49.1 beta-channel daisy.
 
Cc: ajha@chromium.org joshwoodward@chromium.org rponnada@chromium.org
Labels: -Pri-2 -Type-Bug Pri-1 Type-Bug-Regression M-37 ReleaseBlock-Beta
Cc: josa...@chromium.org tturchetto@chromium.org
Cc: nepper@chromium.org
Labels: -ReleaseBlock-Beta ReleaseBlock-Stable

Comment 4 by ajha@chromium.org, May 29 2014

Cc: songsuk@chromium.org kathrelk...@chromium.org
Status: Untriaged
Reproducible on 37.0.2017.3/5899.2.0 dev-channel daisy 
Owner: nepper@chromium.org
Assigning this to Patrick to triage
Labels: -ReleaseBlock-Stable ReleaseBlock-Beta
Rebooting the device also doesn't help in creating a supervised user.
Reproducible on 5899.1.0/37.0.2017.3 - Falco
Cc: antrim@chromium.org mlchan@chromium.org
 Issue 378831  has been merged into this issue.
Labels: -Cr-UI Cr-Services-SupervisedUser

Comment 9 by mbollu@chromium.org, May 29 2014

Labels: -ReleaseBlock-Beta ReleaseBlock-Dev
Reproducible on Link as well. Marking as ReleaseBlock-Dev since we cannot create supervised user. Please change the label if it's not intended.
Are pre-existing users still working after updating to this build?
If so we should move to beta-blocker

Peter, please help routing to right owner 
Pre-existing users are working after update to this build
Cc: -antrim@chromium.org wad@chromium.org nkostylev@chromium.org
Owner: antrim@chromium.org
+wad@/nkostylev@

could you help evaluating this regression on M37?
Labels: Iteration-109
Status: Assigned
Status: Started
Labels: -ReleaseBlock-Dev ReleaseBlock-Beta
moving to beta blocker based on c#11. 
we should still try to get this resolved by next update.
Looks like this is already in the commit queue, thanks for the fast response!
Project Member

Comment 19 by bugdroid1@chromium.org, Jun 3 2014

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/c372422606ac74621f111fbb305d49ca324ddf51

commit c372422606ac74621f111fbb305d49ca324ddf51
Author: antrim@chromium.org <antrim@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98>
Date: Tue Jun 03 12:11:56 2014

Fix parameters order.

BUG= 378338 

Review URL: https://codereview.chromium.org/301353008

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@274476 0039d316-1c4b-4281-b951-d872f2087c98


Project Member

Comment 20 by bugdroid1@chromium.org, Jun 3 2014

------------------------------------------------------------------
r274476 | antrim@chromium.org | 2014-06-03T12:11:56.525748Z

Changed paths:
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/chromeos/login/managed/managed_user_creation_controller_new.cc?r1=274476&r2=274475&pathrev=274476

Fix parameters order.

BUG= 378338 

Review URL: https://codereview.chromium.org/301353008
-----------------------------------------------------------------
Status: Fixed

Comment 22 Deleted

Same error is seen on today's stable build - 36.0.1985.138/5841.83.0 on Daisy

@josafat, Can we get the fix merged to M36 as well ?

Comment 24 by josa...@google.com, Jul 25 2014

Labels: M-36
Status: Assigned
Is the same issue/frequency happening on M36?

antrim/neeper, can you comment if the root cause as in M37?


Cc: antrim@chromium.org
Labels: -Pri-1 Pri-0
Owner: nkostylev@chromium.org
Hi Nikita,

while Denis is out, can you see whether the affected code was present on the M36 branch already, and whether we need to merge back the fix?

Thanks

Patrick
Labels: Iteration-113
Status: Started
Cc: patricia@chromium.org
QA, please check whether this issue reproduces on M37 or not.
Cc: abod...@chromium.org
@abodeti, can you please check this on R37?  thanks.
>> Same error is seen on today's stable build - 36.0.1985.138/5841.83.0 on Daisy

I was unable to reproduce this on latest M36 peppy, just seen  issue 397715 .

>> can you see whether the affected code was present on the M36 branch already, and whether we need to merge back the fix?

No, merge is not needed.

M36 got branched at r@269467, bug was introduced by refactoring CL r272963, fixed in r274476.
>> @abodeti, can you please check this on R37?

Please double check that this issue ("TPM error") really reproduces on M36 as well.
I've seen only  issue 397715 
Not able to reproduce on peppy and daisy with ChromeOS:5978.35.0/Chrome:37.0.2062.50.
This works fine on CrOS 5978.26.0/37.0.2062.29 - Peppy
not reproduced on R36(Chrome:36.0.1985.138/cros:5841.83.0) on peppy and daisy.
Sees like this is not repro on m36 and fix working fine on M37. Anything else on this issue?
 

Cc: timonvo@chromium.org bauerb@chromium.org tzabel@chromium.org pucchakayala@chromium.org benhenry@chromium.org pam@chromium.org royans@chromium.org
 Issue 397715  has been merged into this issue.
I just reproduced this issue with

Version 36.0.1985.126 beta
Platform 5841.73.0 beta-channel daisy
Firmware Google_Snow2695.117.0

Repro steps:

1. From the sign in screen, choose "Create supervised user"
2. In the next dialog, choose "Import existing supervised user", click next

Expected result: Next dialog step is shown

Actual result: Ooops, TPM error message is displayed.
This worked on second try. So this seems to be happening only occasionally.

More detailed repro steps (the ones above were too fuzzy):

Repro steps:

1. From the sign in screen, choose "Create supervised user"
2. Click through the intro screen
3. Select your own account in the next dialog step, click next
4. Choose "Import existing supervised user", click next
5. Choose an existing user, specify a password and click next

Expected result: Confirmation dialog is shown.

Actual result: Ooops, TPM error message is displayed. 
Ok, so seems to be an issue where you import "legacy" supervised users that need their password to be specified manually. So the priority of this issue depends on the number of such legacy supervised users (i.e. created prior to M36).
That's unfortunate that this issue has several reports of having it reproduced but no logs.
The supervised user was not a legacy user, but a supervised user just created on Chrome desktop (canary) (which doesn't have a password).

I will try to reproduce with Chrome OS debug logs being collected.
I think this contains the relevant TPM errors.
debug-log_20140729-131953.tgz
4.0 MB Download
>> a supervised user just created on Chrome desktop (canary) (which doesn't have a password)

Thanks for correction, I forgot about another way to pre-created such users :)
I've just created supervised user on desktop and then imported it on Chrome OS w/o TPM error so it seems to be showing up sometimes.
Thanks for the logs, haven't found anything suspicious or what appears to be different when compared to the successful user creation.
Labels: -ReleaseBlock-Beta ReleaseBlock-Stable
Setting as Stable blocker since m36 is already at Stable channel and it seems like the issue is not happening  all the time
Labels: -Pri-0 -M-36 Pri-1
Status: Assigned
I'm removing M36 release and downgrading to P1 since I was unable to reproduce this reliably.
Nikita, any chance to get a fix for this on m37?
Labels: -Iteration-113 Iteration-114
I was unable to reproduce this issue at all and logs unfortunately doesn't contain useful information. I'll keep trying.

One thing to note is that I've used x86 platform and Patrick has reported this on daisy.
Please let me know in case I can do anything else to help with the investigation.
Here's the error message (in user's Chrome log):

[1650:1650:0729/115408:ERROR:object_proxy.cc(566)] Failed to call method: org.chromium.CryptohomeInterface.AddKeyEx: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

I've just reproduced this on daisy with M38 TOT.
Here's what cryptohomed/chapsd were doint at that time (I'm using logs from comments #41/#43)

2014-07-29T11:53:41.150999+02:00 localhost cryptohomed: Migrated (or created) user directory: /home/.shadow/4c53cb467548c1149d20d5112e800d704b16a387/vault
2014-07-29T11:53:41.159650+02:00 localhost cryptohomed: Creating pass-through directories /home/.shadow/4c53cb467548c1149d20d5112e800d704b16a387/vault/user/Cache
2014-07-29T11:53:41.160350+02:00 localhost cryptohomed: Creating pass-through directories /home/.shadow/4c53cb467548c1149d20d5112e800d704b16a387/vault/user/Downloads
2014-07-29T11:53:41.160917+02:00 localhost cryptohomed: Creating pass-through directories /home/.shadow/4c53cb467548c1149d20d5112e800d704b16a387/vault/user/GCache
2014-07-29T11:53:41.161422+02:00 localhost cryptohomed: Creating pass-through directories /home/.shadow/4c53cb467548c1149d20d5112e800d704b16a387/vault/user/GCache/v1
2014-07-29T11:53:41.161927+02:00 localhost cryptohomed: Creating pass-through directories /home/.shadow/4c53cb467548c1149d20d5112e800d704b16a387/vault/user/GCache/v1/tmp
2014-07-29T11:53:43.329259+02:00 localhost cryptohomed: RecursiveCopy: /home/.shadow/4c53cb467548c1149d20d5112e800d704b16a387/mount/user/.ssh
2014-07-29T11:53:43.331522+02:00 localhost cryptohomed: RecursiveCopy: /home/.shadow/4c53cb467548c1149d20d5112e800d704b16a387/mount/user/log
2014-07-29T11:53:43.356988+02:00 localhost cryptohomed: RecursiveCopy: /home/.shadow/4c53cb467548c1149d20d5112e800d704b16a387/mount/user/.pki
2014-07-29T11:53:43.359288+02:00 localhost cryptohomed: RecursiveCopy: /home/.shadow/4c53cb467548c1149d20d5112e800d704b16a387/mount/user/.pki/nssdb
2014-07-29T11:53:43.400958+02:00 localhost cryptohomed: Skipping binding to /home/chronos/user.
2014-07-29T11:53:43.401032+02:00 localhost cryptohomed: Putting a Pkcs11_Initialize on the mount thread.
2014-07-29T11:53:43.401049+02:00 localhost cryptohomed: Creating new salt at /home/root/4c53cb467548c1149d20d5112e800d704b16a387/chaps/auth_data_salt (0, 0)
2014-07-29T11:53:43.597828+02:00 localhost cryptohomed: Chaps proxy initialized (/org/chromium/Chaps).
2014-07-29T11:53:43.598969+02:00 localhost chapsd: Opening database in: /home/root/4c53cb467548c1149d20d5112e800d704b16a387/chaps
2014-07-29T11:53:43.929185+02:00 localhost chapsd: Importing opencryptoki objects.
2014-07-29T11:53:43.929655+02:00 localhost chapsd: Did not find any opencryptoki objects to import.
2014-07-29T11:53:44.049118+02:00 localhost chapsd: Slot 1 ready for token at /home/root/4c53cb467548c1149d20d5112e800d704b16a387/chaps
2014-07-29T11:53:44.049164+02:00 localhost chapsd: Initializing key hierarchy for token at /home/root/4c53cb467548c1149d20d5112e800d704b16a387/chaps
2014-07-29T11:53:44.050294+02:00 localhost cryptohomed: A Pkcs11_Init event got finished.
2014-07-29T11:53:44.050327+02:00 localhost cryptohomed: PKCS#11 initialization succeeded.
2014-07-29T11:53:44.784711+02:00 localhost cryptohomed: Failed to read keyset file for user 4c53cb467548c1149d20d5112e800d704b16a387
2014-07-29T11:54:18.496005+02:00 localhost chapsd: Finished importing 0 pending objects.
2014-07-29T11:54:18.501328+02:00 localhost chapsd: Master key is ready for token at /home/root/4c53cb467548c1149d20d5112e800d704b16a387/chaps
Another case, happened at 14:50:36

messages

2014-08-14T14:50:00.675476+04:00 localhost cryptohomed[1321]: Asynced Mount() requested. Tracking request sequence id 14 for later PKCS#11 initialization.
2014-08-14T14:50:01.322710+04:00 localhost cryptohomed[1321]: Creating pass-through directories /home/.shadow/86f9e6141b170573d5f3765b724db7c34862ab1a/vault/user/GCache/v1/tmp
2014-08-14T14:50:01.324702+04:00 localhost cryptohomed[1321]: An asynchronous mount request with sequence id: 14 finished; doing PKCS11 init...
2014-08-14T14:50:01.324756+04:00 localhost cryptohomed[1321]: Putting a Pkcs11_Initialize on the mount thread.
2014-08-14T14:50:01.327539+04:00 localhost session_manager[1994]: [INFO:policy_key.cc(63)] No policy key on disk at /home/root/86f9e6141b170573d5f3765b724db7c34862ab1a/session_manager/policy/key
2014-08-14T14:50:01.327950+04:00 localhost session_manager[1994]: [ERROR:policy_store.cc(34)] Could not read policy off disk at /home/root/86f9e6141b170573d5f3765b724db7c34862ab1a/session_manager/policy/policy: No such file or directory
2014-08-14T14:50:01.327980+04:00 localhost session_manager[1994]: [WARNING:user_policy_service_factory.cc(88)] Failed to load user policy data, continuing anyway.
2014-08-14T14:50:01.382795+04:00 localhost cryptohomed[1321]: Chaps proxy initialized (/org/chromium/Chaps).
2014-08-14T14:50:01.383617+04:00 localhost chapsd[1304]: Opening database in: /home/root/86f9e6141b170573d5f3765b724db7c34862ab1a/chaps
2014-08-14T14:50:01.407441+04:00 localhost session_manager[1994]: [INFO:device_policy_service.cc(335)] Loading existing policy.
2014-08-14T14:50:01.407885+04:00 localhost session_manager[1994]: [INFO:device_policy_service.cc(342)] Loading existing settings from policy.
2014-08-14T14:50:01.408234+04:00 localhost session_manager[1994]: [INFO:device_policy_service.cc(386)] Settings updated. User was on the whitelist.
2014-08-14T14:50:01.408510+04:00 localhost session_manager[1994]: [INFO:device_policy_service.cc(391)] Allow new users is 1
2014-08-14T14:50:01.437747+04:00 localhost chapsd[1304]: Slot 1 ready for token at /home/root/86f9e6141b170573d5f3765b724db7c34862ab1a/chaps
2014-08-14T14:50:01.439450+04:00 localhost cryptohomed[1321]: A Pkcs11_Init event got finished.
2014-08-14T14:50:01.439500+04:00 localhost cryptohomed[1321]: PKCS#11 initialization succeeded.
2014-08-14T14:50:01.503395+04:00 localhost cryptohomed[1321]: Chaps proxy initialized (/org/chromium/Chaps).
2014-08-14T14:50:01.610321+04:00 localhost session_manager[1994]: [INFO:session_manager_impl.cc(318)] Starting user session
2014-08-14T14:50:01.976781+04:00 localhost cryptohomed[1321]: Chaps proxy initialized (/org/chromium/Chaps).
2014-08-14T14:50:02.274169+04:00 localhost logger[3881]: /opt/google/input/inputcontrol --mouse_sensitivity=5
2014-08-14T14:50:02.274258+04:00 localhost logger[3880]: /opt/google/input/inputcontrol --touchpad_sensitivity=5 --t5r2_three_finger_click=0 --tapdrag=0
2014-08-14T14:50:03.006668+04:00 localhost session_manager[1994]: [INFO:policy_service.cc(196)] Persisted policy to disk.
2014-08-14T14:50:03.266301+04:00 localhost chapsd[1304]: Master key is ready for token at /home/root/86f9e6141b170573d5f3765b724db7c34862ab1a/chaps
2014-08-14T14:50:11.292416+04:00 localhost cryptohomed[1321]: Migrated (or created) user directory: /home/.shadow/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/vault
2014-08-14T14:50:11.299103+04:00 localhost cryptohomed[1321]: Creating pass-through directories /home/.shadow/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/vault/user/Cache
2014-08-14T14:50:11.299885+04:00 localhost cryptohomed[1321]: Creating pass-through directories /home/.shadow/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/vault/user/Downloads
2014-08-14T14:50:11.300271+04:00 localhost cryptohomed[1321]: Creating pass-through directories /home/.shadow/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/vault/user/GCache
2014-08-14T14:50:11.300577+04:00 localhost cryptohomed[1321]: Creating pass-through directories /home/.shadow/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/vault/user/GCache/v1
2014-08-14T14:50:11.300881+04:00 localhost cryptohomed[1321]: Creating pass-through directories /home/.shadow/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/vault/user/GCache/v1/tmp
2014-08-14T14:50:11.304652+04:00 localhost cryptohomed[1321]: RecursiveCopy: /home/.shadow/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/mount/user/.pki
2014-08-14T14:50:11.305794+04:00 localhost cryptohomed[1321]: RecursiveCopy: /home/.shadow/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/mount/user/.pki/nssdb
2014-08-14T14:50:11.311071+04:00 localhost cryptohomed[1321]: RecursiveCopy: /home/.shadow/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/mount/user/log
2014-08-14T14:50:11.312111+04:00 localhost cryptohomed[1321]: RecursiveCopy: /home/.shadow/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/mount/user/.ssh
2014-08-14T14:50:11.317649+04:00 localhost cryptohomed[1321]: Skipping binding to /home/chronos/user.
2014-08-14T14:50:11.319633+04:00 localhost cryptohomed[1321]: Putting a Pkcs11_Initialize on the mount thread.
2014-08-14T14:50:11.323454+04:00 localhost cryptohomed[1321]: Chaps proxy initialized (/org/chromium/Chaps).
2014-08-14T14:50:11.324812+04:00 localhost chapsd[1304]: Opening database in: /home/root/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/chaps
2014-08-14T14:50:11.386053+04:00 localhost chapsd[1304]: Importing opencryptoki objects.
2014-08-14T14:50:11.386555+04:00 localhost chapsd[1304]: Did not find any opencryptoki objects to import.
2014-08-14T14:50:11.391769+04:00 localhost chapsd[1304]: Slot 2 ready for token at /home/root/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/chaps
2014-08-14T14:50:11.393125+04:00 localhost chapsd[1304]: Initializing key hierarchy for token at /home/root/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/chaps
2014-08-14T14:50:11.394276+04:00 localhost cryptohomed[1321]: A Pkcs11_Init event got finished.
2014-08-14T14:50:11.394706+04:00 localhost cryptohomed[1321]: PKCS#11 initialization succeeded.
2014-08-14T14:50:12.101606+04:00 localhost cryptohomed[1321]: Failed to read keyset file for user f6c1b9f5554680baa38435ba7fbcbae08540f6f2
2014-08-14T14:50:13.445061+04:00 localhost cras_server[2971]: No chmap queried!
2014-08-14T14:50:13.445680+04:00 localhost cras_server[2971]: no enabled source or sink found (nil)/0xb5b004a8 for playback
2014-08-14T14:50:13.445710+04:00 localhost cras_server[2971]: cannot create pipeline
2014-08-14T14:50:14.900556+04:00 localhost metrics_daemon[3002]: [WARNING:metrics_daemon.cc(500)] found 1 items in /sys/class/block/mmcblk0/stat, expected 2
2014-08-14T14:50:15.872334+04:00 localhost metrics_daemon[3002]: [WARNING:metrics_daemon.cc(500)] found 1 items in /sys/class/block/mmcblk0/stat, expected 2
2014-08-14T14:50:38.705390+04:00 localhost chapsd[1304]: Finished importing 0 pending objects.
2014-08-14T14:50:38.710333+04:00 localhost chapsd[1304]: Master key is ready for token at /home/root/f6c1b9f5554680baa38435ba7fbcbae08540f6f2/chaps

user chrome log (also in /var/log/ui/ui.LATEST)

[2026:2026:0814/145036:ERROR:logging.h(739)] Failed to call method: org.chromium.CryptohomeInterface.AddKeyEx: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
log-081414-145218.tar.gz
823 KB Download
Owner: wad@chromium.org
Cryptohome error: MountError::MOUNT_ERROR_FATAL

Reassigning to Will.
With additional logging (https://codereview.chromium.org/472833002)

AddKeyEx failure happened at 162812 and then at 16:28:18 there're messages about successful chapsd operation
2014-08-14T16:28:18.764918+04:00 localhost chapsd[1304]: Finished importing 0 pending objects.
2014-08-14T16:28:18.770761+04:00 localhost chapsd[1304]: Master key is ready for token at /home/root/ee01b1ebfdaea650755bb2135ee4af00b1f72648/chaps




[358:358:0814/162812:ERROR:logging.h(739)] Failed to call method: org.chromium.CryptohomeInterface.AddKeyEx: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
[358:358:0814/162812:ERROR:extended_authenticator.cc(339)] Supervised user cryptohome error, code: 1
[358:358:0814/162812:ERROR:supervised_user_creation_screen.cc(374)] Supervised user creation failure, code: 2

messages:

2014-08-14T16:27:36.191834+04:00 localhost cryptohomed[1321]: An asynchronous mount request with sequence id: 47 finished; doing PKCS11 init...
2014-08-14T16:27:36.191879+04:00 localhost cryptohomed[1321]: Putting a Pkcs11_Initialize on the mount thread.
2014-08-14T16:27:36.194843+04:00 localhost session_manager[326]: [INFO:policy_key.cc(63)] No policy key on disk at /home/root/86f9e6141b170573d5f3765b724db7c34862ab1a/session_manager/policy/key
2014-08-14T16:27:36.195276+04:00 localhost session_manager[326]: [ERROR:policy_store.cc(34)] Could not read policy off disk at /home/root/86f9e6141b170573d5f3765b724db7c34862ab1a/session_manager/policy/policy: No such file or directory
2014-08-14T16:27:36.195311+04:00 localhost session_manager[326]: [WARNING:user_policy_service_factory.cc(88)] Failed to load user policy data, continuing anyway.
2014-08-14T16:27:36.198158+04:00 localhost cryptohomed[1321]: Chaps proxy initialized (/org/chromium/Chaps).
2014-08-14T16:27:36.204291+04:00 localhost chapsd[1304]: Opening database in: /home/root/86f9e6141b170573d5f3765b724db7c34862ab1a/chaps
2014-08-14T16:27:36.238675+04:00 localhost chapsd[1304]: Slot 1 ready for token at /home/root/86f9e6141b170573d5f3765b724db7c34862ab1a/chaps
2014-08-14T16:27:36.241834+04:00 localhost cryptohomed[1321]: A Pkcs11_Init event got finished.
2014-08-14T16:27:36.242358+04:00 localhost cryptohomed[1321]: PKCS#11 initialization succeeded.
2014-08-14T16:27:36.268654+04:00 localhost session_manager[326]: [INFO:device_policy_service.cc(335)] Loading existing policy.
2014-08-14T16:27:36.271963+04:00 localhost session_manager[326]: [INFO:device_policy_service.cc(342)] Loading existing settings from policy.
2014-08-14T16:27:36.272068+04:00 localhost session_manager[326]: [INFO:device_policy_service.cc(386)] Settings updated. User was on the whitelist.
2014-08-14T16:27:36.272134+04:00 localhost session_manager[326]: [INFO:device_policy_service.cc(391)] Allow new users is 1
2014-08-14T16:27:36.282340+04:00 localhost cryptohomed[1321]: Chaps proxy initialized (/org/chromium/Chaps).
2014-08-14T16:27:36.448039+04:00 localhost session_manager[326]: [INFO:session_manager_impl.cc(318)] Starting user session
2014-08-14T16:27:36.889852+04:00 localhost cryptohomed[1321]: Chaps proxy initialized (/org/chromium/Chaps).
2014-08-14T16:27:37.123921+04:00 localhost logger[1842]: /opt/google/input/inputcontrol --mouse_sensitivity=5
2014-08-14T16:27:37.142505+04:00 localhost logger[1844]: /opt/google/input/inputcontrol --touchpad_sensitivity=5 --t5r2_three_finger_click=0 --tapdrag=0
2014-08-14T16:27:38.060826+04:00 localhost chapsd[1304]: Master key is ready for token at /home/root/86f9e6141b170573d5f3765b724db7c34862ab1a/chaps
2014-08-14T16:27:38.115573+04:00 localhost session_manager[326]: [INFO:policy_service.cc(196)] Persisted policy to disk.
2014-08-14T16:27:44.896547+04:00 localhost metrics_daemon[3002]: [WARNING:metrics_daemon.cc(500)] found 1 items in /sys/class/block/mmcblk0/stat, expected 2
2014-08-14T16:27:45.871375+04:00 localhost metrics_daemon[3002]: [WARNING:metrics_daemon.cc(500)] found 1 items in /sys/class/block/mmcblk0/stat, expected 2
2014-08-14T16:27:47.326778+04:00 localhost cryptohomed[1321]: Migrated (or created) user directory: /home/.shadow/ee01b1ebfdaea650755bb2135ee4af00b1f72648/vault
2014-08-14T16:27:47.330678+04:00 localhost cryptohomed[1321]: Creating pass-through directories /home/.shadow/ee01b1ebfdaea650755bb2135ee4af00b1f72648/vault/user/Cache
2014-08-14T16:27:47.331246+04:00 localhost cryptohomed[1321]: Creating pass-through directories /home/.shadow/ee01b1ebfdaea650755bb2135ee4af00b1f72648/vault/user/Downloads
2014-08-14T16:27:47.331678+04:00 localhost cryptohomed[1321]: Creating pass-through directories /home/.shadow/ee01b1ebfdaea650755bb2135ee4af00b1f72648/vault/user/GCache
2014-08-14T16:27:47.332078+04:00 localhost cryptohomed[1321]: Creating pass-through directories /home/.shadow/ee01b1ebfdaea650755bb2135ee4af00b1f72648/vault/user/GCache/v1
2014-08-14T16:27:47.332470+04:00 localhost cryptohomed[1321]: Creating pass-through directories /home/.shadow/ee01b1ebfdaea650755bb2135ee4af00b1f72648/vault/user/GCache/v1/tmp
2014-08-14T16:27:47.334740+04:00 localhost cryptohomed[1321]: RecursiveCopy: /home/.shadow/ee01b1ebfdaea650755bb2135ee4af00b1f72648/mount/user/.pki
2014-08-14T16:27:47.335425+04:00 localhost cryptohomed[1321]: RecursiveCopy: /home/.shadow/ee01b1ebfdaea650755bb2135ee4af00b1f72648/mount/user/.pki/nssdb
2014-08-14T16:27:47.338139+04:00 localhost cryptohomed[1321]: RecursiveCopy: /home/.shadow/ee01b1ebfdaea650755bb2135ee4af00b1f72648/mount/user/log
2014-08-14T16:27:47.338779+04:00 localhost cryptohomed[1321]: RecursiveCopy: /home/.shadow/ee01b1ebfdaea650755bb2135ee4af00b1f72648/mount/user/.ssh
2014-08-14T16:27:47.340000+04:00 localhost cryptohomed[1321]: Skipping binding to /home/chronos/user.
2014-08-14T16:27:47.341660+04:00 localhost cryptohomed[1321]: Putting a Pkcs11_Initialize on the mount thread.
2014-08-14T16:27:47.352425+04:00 localhost cryptohomed[1321]: Chaps proxy initialized (/org/chromium/Chaps).
2014-08-14T16:27:47.359262+04:00 localhost chapsd[1304]: Opening database in: /home/root/ee01b1ebfdaea650755bb2135ee4af00b1f72648/chaps
2014-08-14T16:27:47.429442+04:00 localhost chapsd[1304]: Importing opencryptoki objects.
2014-08-14T16:27:47.429953+04:00 localhost chapsd[1304]: Did not find any opencryptoki objects to import.
2014-08-14T16:27:47.434509+04:00 localhost chapsd[1304]: Slot 2 ready for token at /home/root/ee01b1ebfdaea650755bb2135ee4af00b1f72648/chaps
2014-08-14T16:27:47.434839+04:00 localhost chapsd[1304]: Initializing key hierarchy for token at /home/root/ee01b1ebfdaea650755bb2135ee4af00b1f72648/chaps
2014-08-14T16:27:47.436065+04:00 localhost cryptohomed[1321]: A Pkcs11_Init event got finished.
2014-08-14T16:27:47.436106+04:00 localhost cryptohomed[1321]: PKCS#11 initialization succeeded.
2014-08-14T16:27:48.161382+04:00 localhost cryptohomed[1321]: Failed to read keyset file for user ee01b1ebfdaea650755bb2135ee4af00b1f72648
2014-08-14T16:27:48.380983+04:00 localhost cras_server[2971]: No chmap queried!
2014-08-14T16:27:48.381030+04:00 localhost cras_server[2971]: no enabled source or sink found (nil)/0xb5b004a8 for playback
2014-08-14T16:27:48.381049+04:00 localhost cras_server[2971]: cannot create pipeline
2014-08-14T16:28:14.903178+04:00 localhost metrics_daemon[3002]: [WARNING:metrics_daemon.cc(500)] found 1 items in /sys/class/block/mmcblk0/stat, expected 2
2014-08-14T16:28:15.873503+04:00 localhost metrics_daemon[3002]: [WARNING:metrics_daemon.cc(500)] found 1 items in /sys/class/block/mmcblk0/stat, expected 2
2014-08-14T16:28:18.764918+04:00 localhost chapsd[1304]: Finished importing 0 pending objects.
2014-08-14T16:28:18.770761+04:00 localhost chapsd[1304]: Master key is ready for token at /home/root/ee01b1ebfdaea650755bb2135ee4af00b1f72648/chaps
log-081414-164305_fail-162812.tar.gz
908 KB Download
Project Member

Comment 58 by bugdroid1@chromium.org, Aug 15 2014

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/648524375ee1e1a7a7d955ca6f33d4dcf70dfef7

commit 648524375ee1e1a7a7d955ca6f33d4dcf70dfef7
Author: nkostylev@chromium.org <nkostylev@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98>
Date: Fri Aug 15 05:15:01 2014

Additional logs for supervised user auth/creation errors.

BUG= 378338 

Review URL: https://codereview.chromium.org/472833002

Cr-Commit-Position: refs/heads/master@{#289797}
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@289797 0039d316-1c4b-4281-b951-d872f2087c98


Analyzing comment #56 logs.

According to logs it seems that there's a race:

1. Supervised user cryptohome is created

2014-08-14T16:27:47.326778+04:00 localhost cryptohomed[1321]: Migrated (or created) user directory: /home/.shadow/ee01b1ebfdaea650755bb2135ee4af00b1f72648/vault

2. chapsd starts initialization

2014-08-14T16:27:47.434839+04:00 localhost chapsd[1304]: Initializing key hierarchy for token at /home/root/ee01b1ebfdaea650755bb2135ee4af00b1f72648/chaps

3. Chrome calls cryptohome's AddKeyEx which fails with MountError::MOUNT_ERROR_FATAL

[358:358:0814/162812:ERROR:logging.h(739)] Failed to call method: org.chromium.CryptohomeInterface.AddKeyEx: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

4. chapsd finishes initialization for newly created cryptohome:

2014-08-14T16:28:18.764918+04:00 localhost chapsd[1304]: Finished importing 0 pending objects.
2014-08-14T16:28:18.770761+04:00 localhost chapsd[1304]: Master key is ready for token at /home/root/ee01b1ebfdaea650755bb2135ee4af00b1f72648/chaps
Owner: nkostylev@chromium.org
According to c#22 and c#31/c#32 issue was not repro on m37

Nikita, can you confirm if race condition on c#59 would be on m37 too? 

Owner: wad@chromium.org
I've just reproduced this on daisy 37.0.2062.89 (Platform 5978.55.0-14.08.17).
Same errors in logs.

Since this is a race it reproduces from time to time but quite often.

Out of 15 retries I've got 6 failures and 9 successfully created users.

Comment 62 by wad@chromium.org, Aug 19 2014

Cc: usanghi@chromium.org
DBus replies should be on the DBus thread for all *Ex calls.  chaps work should always be triggered from the mount thread, so this is pretty weird, but maybe there is still some lingering post-creation code in the dbus thread.

Comment 63 by wad@chromium.org, Aug 19 2014

Cc: dkrahn@chromium.org
Following the AddKeyEx client code in Chrome, that looks like a synthetic failure due to Chrome's call timing out (it uses the default object proxy time out). 

Reviewing the AddKeyEx code in cryptohome and the logs nikita trimmed down, it looks like the handling for AddKeyEx is in line behind a Mount::InsertPkcs11Token() call on the mount_thread.

So our solution is one of:
(1) Have Chrome wait longer before timing out
(2) Add a pkcs#11 specific thread back to cryptohome (data access issues would be the main concern)
(3) Make the chaps client asynchronous and bind a callback for when it completes

#3 is the right solution, but I'm not sure how much work it'll be yet nor if it'd be mergeable.  There are concerning edge cases that'd need to be addressed that are currently "safe" because of the linear servicing of DBus methods.

#1 is the simplest solution as line 757 of cryptohome_client.cc in Chrome can be changed to accept a longer time out. I believe the DBus default is 25 seconds and it looks like we would want at least 40 seconds (if not a whole minute).

It is unsurprising that this is occurring more on daisy because its TPM is the slowest.

Does it seem reasonable to start with a Chrome timeout change as that would be a one line merge, then see what we can do on ToT for making pkcs#11 init safely asynchronous (or at least non-blocking where it shouldn't be)?

Cc: -timonvo@chromium.org

Comment 65 Deleted

If the chaps client call is async on the client side, how does that affect how the Dbus calls are handled on the service?
However I do agree that fixing changing the call timeout is a decent temporary fix.

Comment 67 by wad@chromium.org, Aug 19 2014

Re #66, if the chaps client is async, then the reply should trigger a new callback to be scheduled on the mount_thread.  Right now, all method work is done on the mount_thread, but the dbus calls themselves are handled on the dbus thread (so cryptohome is always responsive at a dbus level).  

My main concern with making chaps client async is that we'll need to a mount ref is kept around in case of a quick mount/umount call pair. [It also doesn't help that Unmount() hasn't been make glib async yet and still runs on the dbus thread.]

I thought AddKeyEx was an asynchronous call in Chrome's CryptohomeClient. Or is the new async call style limited by the default timeout? In any case, any dbus call that depends on the TPM directly or indirectly should should have a timeout of at least 90 seconds.

Re #63: I disagree that #3 is the right fix. The chaps call itself is quick b/c chapsd does the expensive work in the background. The problem is TPM contention and software can do nothing but wait. IMHO, #1 is both the right fix and the easy fix :)
Labels: M-38
My 2c, going with the lowest risk solution on M37 sounds like the right approach here as we are one or two betas away from Stable

Will, are you creating CL for this? we could get that to m-38 dev and then merge to m37. 

We can then focus on longer term (if different) for ToT

Comment 70 by wad@chromium.org, Aug 20 2014

Josafat, I don't have a Chrome checkout and my committer status is somewhat broken.  If someone already has everything in order, then it'd be great to have them go ahead and land this quickly.  If not, I'll start pull and fixing things up.
Owner: antrim@chromium.org

Comment 72 by wad@chromium.org, Aug 21 2014

Re #68, dkrahn is exactly right. The chaps client is already async, so what we're seeing is a slow TPM slowing the AddKeyEx reply.  The timeout fix is the right one - namely around the order of bumping it to 120s.

Thanks!
Status: Started
In CQ now https://codereview.chromium.org/491913002/
Project Member

Comment 74 by bugdroid1@chromium.org, Aug 21 2014

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/347c06e12684f5c2c82049950b1a94448e14e30f

commit 347c06e12684f5c2c82049950b1a94448e14e30f
Author: antrim@chromium.org <antrim@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98>
Date: Thu Aug 21 15:37:31 2014

Increase DBus timeout in cryptohome calls to 2 minutes.

BUG= 378338 

Review URL: https://codereview.chromium.org/491913002

Cr-Commit-Position: refs/heads/master@{#291080}
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@291080 0039d316-1c4b-4281-b951-d872f2087c98


Project Member

Comment 75 by bugdroid1@chromium.org, Aug 21 2014

------------------------------------------------------------------
r291080 | antrim@chromium.org | 2014-08-21T15:37:31.153517Z

Changed paths:
   M http://src.chromium.org/viewvc/chrome/trunk/src/chromeos/dbus/cryptohome_client.cc?r1=291080&r2=291079&pathrev=291080

Increase DBus timeout in cryptohome calls to 2 minutes.

BUG= 378338 

Review URL: https://codereview.chromium.org/491913002
-----------------------------------------------------------------
I've tested it on daisy, 12 supervised users imported, no failures (3 of them took more than a minute though).
please merge-request once validation is complete
Labels: Merge-Approved
I did not see your c#76. Please merge to M-37 and M-38
ping?
Project Member

Comment 80 by bugdroid1@chromium.org, Aug 25 2014

Labels: -Merge-Approved merge-merged-2125
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/a08656d588a948bce7a53c4f6b77595e32102e6c

commit a08656d588a948bce7a53c4f6b77595e32102e6c
Author: Pavel Sergeev <dzhioev@chromium.org>
Date: Mon Aug 25 13:26:08 2014

Increase DBus timeout in cryptohome calls to 2 minutes.

BUG= 378338 

Review URL: https://codereview.chromium.org/491913002

Cr-Commit-Position: refs/heads/master@{#291080}
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@291080 0039d316-1c4b-4281-b951-d872f2087c98
(cherry picked from commit 347c06e12684f5c2c82049950b1a94448e14e30f)

Review URL: https://codereview.chromium.org/499303002

Cr-Commit-Position: refs/branch-heads/2125@{#76}
Cr-Branched-From: b68026d94bda36dd106a3d91a098719f952a9477-refs/heads/master@{#290040}

[modify] https://chromium.googlesource.com/chromium/src.git/+/a08656d588a948bce7a53c4f6b77595e32102e6c/chromeos/dbus/cryptohome_client.cc

Project Member

Comment 81 by bugdroid1@chromium.org, Aug 25 2014

Labels: merge-merged-2062
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/bb7f417ce8466dc854bf114b09b782d253911976

commit bb7f417ce8466dc854bf114b09b782d253911976
Author: Pavel Sergeev <dzhioev@chromium.org>
Date: Mon Aug 25 13:34:57 2014

Increase DBus timeout in cryptohome calls to 2 minutes.

BUG= 378338 

Review URL: https://codereview.chromium.org/491913002

Cr-Commit-Position: refs/heads/master@{#291080}
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@291080 0039d316-1c4b-4281-b951-d872f2087c98
(cherry picked from commit 347c06e12684f5c2c82049950b1a94448e14e30f)

Conflicts:
	chromeos/dbus/cryptohome_client.cc

Review URL: https://codereview.chromium.org/505523004

Cr-Commit-Position: refs/branch-heads/2062@{#572}
Cr-Branched-From: 2e531f7c26d0d9e2aa0cced17a35eea6687dc58c-refs/heads/master@{#278856}

[modify] https://chromium.googlesource.com/chromium/src.git/+/bb7f417ce8466dc854bf114b09b782d253911976/chromeos/dbus/cryptohome_client.cc

Status: Fixed
Status: Verified

Google Chrome	37.0.2062.120 (Official Build 6b29c9a) 
Platform	5978.98.0 (Official Build) stable-channel peppy

Sign in to add a comment