ChromeOS: Owner detection is flagile, especially for the first sign-in. |
|||||||||
Issue descriptionChrome Version: 59.0.3054.0 OS: R59-9413.0.0 I encountered this issue while investigating the internal bug b/34661187, which is about very flaky test concerning ARC. What steps will reproduce the problem? (1) Run autotest `test_that cheets_CTSHelper` What is the expected result? It automatically signs in and recognized as an owner user (for instance, owner-only settings can be modified.) What happens instead? Recognized as a regular user. Here's what's happening, as far as I understand. 1) During the first-run log-in screen, DeviceSettingsProvider falls into PERMANENTLY_UNTRUSTED state because there's no owner public key set yet: https://chromium.googlesource.com/chromium/src/+/459465b1d6d569a612b16526a30af878a8df1b10/chrome/browser/chromeos/settings/device_settings_provider.cc#879 2) After the first user signed in, the user becomes the owner, public key is written, and the following code of DeviceSettingsService is called: https://chromium.googlesource.com/chromium/src/+/29783ad5a5cbc0569d4a5578c82feca23223a621/chrome/browser/chromeos/settings/device_settings_service.cc#314 if (GetOwnershipStatus() != previous_ownership_status_) { previous_ownership_status_ = GetOwnershipStatus(); NotifyOwnershipStatusChanged(); } NotifyDeviceSettingsUpdated(); 3) NotifyOwnershipStatusChanged() kicks UserManager to update the ownership status: https://chromium.googlesource.com/chromium/src/+/29783ad5a5cbc0569d4a5578c82feca23223a621/chrome/browser/chromeos/login/users/chrome_user_manager_impl.cc#450 RetrieveTrustedDevicePolicies(); UpdateOwnership(); but RetrieveTrustedDevicePolicies fails, because the DeviceSettingsProvider is in PERMANENTLY_UNTRUSTED state. Since it is PERMANENTLY_UNTRUSTED, even the retry call back is registered. As a result, SetOwnerId(AccountId::FromUserEmail(owner_email)) is not call, no matter how the user waits long. 4) UpdateOwnership() also fails in high chance, because it assumes the private key is already loaded and does synchronous call DeviceSettingsService::Get()->HasPrivateOwnerKey(). At this point, only public key may be available and not retry is performed, no matter how the user waits long. 5) Let's get back to the last line of (2). NotifyDeviceSettingsUpdated() is called, which eventually reaches here: https://chromium.googlesource.com/chromium/src/+/459465b1d6d569a612b16526a30af878a8df1b10/chrome/browser/chromeos/settings/device_settings_provider.cc#852 and gets DeviceSettingsProvider back to the TRUSTED state, but it's too late. The step (3) had already failed. (3) makes chromeos::LoginState::Get()->GetLoggedInUserType() wrong. (4) makes user_manager::UserManager::Get()->GetOwnerAccountId() wrong. I think it is unavoidable to have these checks behave wrongly for a short while after boot, but it should not persist. +xiyuan from UserManager OWNER +tnagel from cros/settings OWNER Could you folks have any ideas on fixing these?
,
Mar 30 2017
(small correction) 3) even the retry call back is registered. ==> callback is NOT registered.
,
Mar 30 2017
Let me give it a shot since I have a WIP CL (https://codereview.chromium.org/2779973007/) for issue 702308 . I would need to extend it to cover RetrieveTrustedDevicePolicies failure for the first sign-in case. Instead of mapping STORE_KEY_UNAVAILABLE to TEMPORARILY_UNTRUSTED, we probably can move NotifyDeviceSettingsUpdated() before NotifyOwnershipStatusChanged() in DeviceSettingsService. This way, RetrieveTrustedDevicePolicies would happen after DeviceSettingsProvider goes back to TRUSTED state. This should fix 3).
,
Mar 30 2017
Cool. Thanks! I didn't realize the issue 702308 . Yes, altering the method call order is indeed another way.
,
Mar 30 2017
+achuith
,
Mar 30 2017
Looks like reordering the call could cause temporarily cached changes to be load because DeviceSettingsProvider::UpdateFromService will overwrite its cached |device_settings_|. Will look at mapping STORE_KEY_UNAVAILABLE to TEMPORARILY_UNTRUSTED when there is no public key, i.e. when DeviceSetttingService::GetOwnershipStatus() is not OWNERSHIP_TAKEN.
,
Mar 30 2017
I am unable to repro the RetrieveTrustedDevicePolicies failure either for a first sign-in user or an existing user. - For first sign-in user case, I saw STORE_KEY_UNAVAILABLE triggers a PERMANENTLY_UNTRUSTED. However, DeviceSettingsProvider::OwnershipStatusChanged is called after owner key is created and loaded. In this case, both public and private keys are loaded and we change from OWNERSHIP_NONE -> TAKEN. Hence line 690 [1] runs to set TEMPORARILY_UNTRUSTED and overwrite the STORE_KEY_UNAVAILABLE case before RetrieveTrustedDevicePolicies. As a result, RetrieveTrustedDevicePolicies works as expected. - For existing user, we don't hit STORE_KEY_UNAVAILABLE. DeviceSettingsProvider::UpdateFromService will be called to set TEMPORARILY_UNTRUSTED. RetrieveTrustedDevicePolicies works in this case too. I am now inclined to think this issue is actually the same of issue 702308 that LoginState::GetLoggedInUserType does not return a correct value for owner. [1]: https://cs.chromium.org/chromium/src/chrome/browser/chromeos/settings/device_settings_provider.cc?rcl=e6b2fb315a37379020c437f9e28d7b921e273410&l=690
,
Mar 30 2017
> In this case, both public and private keys are loaded The problem I'm seeing in this case is when private key is not loaded yet at this point (and it comes soon later.) This case the overwrite does not happen. It happens for me in a very high prob on Samus but not on other devices.
,
Mar 30 2017
Sounds like we might have a race. The private key is loaded in OwnerSettingsService and DeviceSettingsService loads the public key independently of that. Maybe DeviceSettingsService code finishes first on your device somehow.
,
Mar 31 2017
Yes it's a race. There may be a intra-Chrome race but more than that, loading a public key is just about reading a file, https://cs.chromium.org/chromium/src/components/ownership/owner_key_util_impl.cc?type=cs&l=25 while loading a private key needs to wait NSS/TPM per profile to be setup https://cs.chromium.org/chromium/src/chrome/browser/chromeos/ownership/owner_settings_service_chromeos.cc?type=cs&l=68 which is presumably more time consuming step not in sync with public key loading.
,
Mar 31 2017
Ignore my comment #10. You're absolutely right in the comment #9. Inserted quite a few LOG(ERROR)<<"@@@"<<__func__<<"@@@" everywhere: GOOD CASE [20962:20962:0331/031627.057691:ERROR:owner_settings_service_chromeos.cc(344)] @@@Observe@@@ ReloadKeypair[from NOTIFICATION_PROFILE_CREATED] [0331/031627:INFO:keygen_worker.cc(48)] Generating Owner key. [20962:20962:0331/031627.174318:ERROR:owner_settings_service_chromeos.cc(245)] @@@OnTPMTokenReady@@@ ReloadKeypair[from OnTPMTokeReady] [20962:21006:0331/031627.174466:ERROR:owner_key_util_impl.cc(30)] Could not get size of /var/lib/whitelist/owner.key [20962:21006:0331/031627.174502:ERROR:owner_settings_service_chromeos.cc(118)] @@@LoadPrivateKey@@@ Failed to load owner public key. [20962:20962:0331/031627.175206:ERROR:owner_settings_service.cc(153)] @@@OnKeypairLoaded@@@ public=not loaded private=not loaded [0331/031627:INFO:keygen_worker.cc(55)] Writing Owner key to /home/user/60adbc4523339631e639ea888810cb88cfa13fe3/key.pub [0331/031627:INFO:policy_key.cc(122)] wrote 294 bytes to /home/user/60adbc4523339631e639ea888810cb88cfa13fe3/key.pub [20962:20962:0331/031627.433837:ERROR:owner_settings_service_chromeos.cc(352)] @@@OwnerKeySet@@@ ReloadKeypair[from OwnerKeySet] [20962:21008:0331/031627.435381:ERROR:session_manager_operation.cc(118)] @@@LoadPublicKey@@@ DeviceSettingsService wanted publickey, is_loaded?: 1 [20962:21008:0331/031627.435434:ERROR:owner_settings_service_chromeos.cc(126)] @@@LoadPrivateKey@@@ Succeeded to load owner public key. [20962:20996:0331/031627.437584:ERROR:owner_settings_service_chromeos.cc(80)] @@@LoadPrivateKeyByPublicKey@@@ Loading private key: private_slot=0xfe5d6baa000 [20962:20996:0331/031629.159554:ERROR:owner_settings_service_chromeos.cc(95)] @@@LoadPrivateKeyByPublicKey@@@ not found in private_slot [20962:20962:0331/031629.194799:ERROR:owner_settings_service.cc(153)] @@@OnKeypairLoaded@@@ public=loaded private=loaded ***************************** AT THIS POINT owner_settings_service gets private key *************************************************** [20962:21006:0331/031629.194930:ERROR:session_manager_operation.cc(118)] @@@LoadPublicKey@@@ DeviceSettingsService wanted publickey, is_loaded?: 1 [20962:20962:0331/031629.203333:ERROR:device_settings_service.cc(315)] @@@HandleCompletedOperation@@@ Ownership status 1 -> 2 ***************************** AT THIS POINT device_settings_service gets public key and updates/notifies ownership ******************** [20962:20962:0331/031629.203384:ERROR:device_settings_service.cc(319)] @@@HandleCompletedOperation@@@ NotifyOwnershipStatusChanged [20962:20962:0331/031629.203445:ERROR:chrome_user_manager_impl.cc(690)] @@@RetrieveTrustedDevicePolicies@@@ PrepareTrustedValues returned 1 [20962:20962:0331/031629.203466:VERBOSE1:chrome_user_manager_impl.cc(957)] Current user is owner [20962:20962:0331/031629.203836:ERROR:device_settings_service.cc(322)] @@@HandleCompletedOperation@@@ NotifyDeviceSettingsUpdated [20962:20962:0331/031629.203977:ERROR:chrome_user_manager_impl.cc(690)] @@@RetrieveTrustedDevicePolicies@@@ PrepareTrustedValues returned 1 [20962:20962:0331/031629.493955:ERROR:device_settings_service.cc(315)] @@@HandleCompletedOperation@@@ Ownership status 2 -> 2 [20962:20962:0331/031629.493981:ERROR:device_settings_service.cc(322)] @@@HandleCompletedOperation@@@ NotifyDeviceSettingsUpdated [20962:20962:0331/031629.494139:ERROR:chrome_user_manager_impl.cc(690)] @@@RetrieveTrustedDevicePolicies@@@ PrepareTrustedValues returned 1 [20962:20962:0331/031629.607620:ERROR:device_settings_service.cc(315)] @@@HandleCompletedOperation@@@ Ownership status 2 -> 2 [20962:20962:0331/031629.607654:ERROR:device_settings_service.cc(322)] @@@HandleCompletedOperation@@@ NotifyDeviceSettingsUpdated [20962:20962:0331/031629.607737:ERROR:chrome_user_manager_impl.cc(690)] @@@RetrieveTrustedDevicePolicies@@@ PrepareTrustedValues returned 0 BAD CASE [0331/031953:INFO:keygen_worker.cc(48)] Generating Owner key. [24386:24386:0331/031953.094552:ERROR:owner_settings_service_chromeos.cc(344)] @@@Observe@@@ ReloadKeypair[from NOTIFICATION_PROFILE_CREATED] [24386:24386:0331/031953.183576:ERROR:owner_settings_service_chromeos.cc(245)] @@@OnTPMTokenReady@@@ ReloadKeypair[from OnTPMTokeReady] [24386:24431:0331/031953.183760:ERROR:owner_key_util_impl.cc(30)] Could not get size of /var/lib/whitelist/owner.key [24386:24431:0331/031953.183857:ERROR:owner_settings_service_chromeos.cc(118)] @@@LoadPrivateKey@@@ Failed to load owner public key. [24386:24386:0331/031953.184199:ERROR:owner_settings_service.cc(153)] @@@OnKeypairLoaded@@@ public=not loaded private=not loaded [24386:24386:0331/031953.322152:ERROR:multi_user_window_manager_stub.cc(60)] Not implemented reached in virtual void chrome::MultiUserWindowManagerStub::RemoveObserver(chrome::MultiUserWindowManager::Observer *) [0331/031953:INFO:keygen_worker.cc(55)] Writing Owner key to /home/user/60adbc4523339631e639ea888810cb88cfa13fe3/key.pub [0331/031953:INFO:policy_key.cc(122)] wrote 294 bytes to /home/user/60adbc4523339631e639ea888810cb88cfa13fe3/key.pub [24386:24386:0331/031953.591978:ERROR:owner_settings_service_chromeos.cc(352)] @@@OwnerKeySet@@@ ReloadKeypair[from OwnerKeySet] [24386:24423:0331/031953.592078:ERROR:owner_settings_service_chromeos.cc(126)] @@@LoadPrivateKey@@@ Succeeded to load owner public key. [24386:24428:0331/031953.592333:ERROR:session_manager_operation.cc(118)] @@@LoadPublicKey@@@ DeviceSettingsService wanted publickey, is_loaded?: 1 [24386:24418:0331/031953.592803:ERROR:owner_settings_service_chromeos.cc(80)] @@@LoadPrivateKeyByPublicKey@@@ Loading private key: private_slot=0x2951d8b77580 [24386:24386:0331/031953.603108:ERROR:device_settings_service.cc(315)] @@@HandleCompletedOperation@@@ Ownership status 1 -> 2 ***************************** AT THIS POINT device_settings_service gets public key and updates/notifies ownership ******************** [24386:24386:0331/031953.603156:ERROR:device_settings_service.cc(319)] @@@HandleCompletedOperation@@@ NotifyOwnershipStatusChanged [24386:24386:0331/031953.603214:ERROR:chrome_user_manager_impl.cc(690)] @@@RetrieveTrustedDevicePolicies@@@ PrepareTrustedValues returned 2 [24386:24386:0331/031953.603237:VERBOSE1:chrome_user_manager_impl.cc(957)] Current user is not owner [24386:24386:0331/031953.603286:ERROR:device_settings_service.cc(322)] @@@HandleCompletedOperation@@@ NotifyDeviceSettingsUpdated [24386:24418:0331/031955.073303:ERROR:owner_settings_service_chromeos.cc(95)] @@@LoadPrivateKeyByPublicKey@@@ not found in private_slot [24386:24386:0331/031955.074500:ERROR:owner_settings_service.cc(153)] @@@OnKeypairLoaded@@@ public=loaded private=loaded ***************************** AT THIS POINT owner_settings_service gets private key *************************************************** [24386:24423:0331/031955.074814:ERROR:session_manager_operation.cc(118)] @@@LoadPublicKey@@@ DeviceSettingsService wanted publickey, is_loaded?: 1 [24386:24386:0331/031955.077499:ERROR:device_settings_service.cc(315)] @@@HandleCompletedOperation@@@ Ownership status 2 -> 2 [24386:24386:0331/031955.077586:ERROR:device_settings_service.cc(322)] @@@HandleCompletedOperation@@@ NotifyDeviceSettingsUpdated [24386:24386:0331/031955.229734:ERROR:device_settings_service.cc(315)] @@@HandleCompletedOperation@@@ Ownership status 2 -> 2 [24386:24386:0331/031955.229762:ERROR:device_settings_service.cc(322)] @@@HandleCompletedOperation@@@ NotifyDeviceSettingsUpdated
,
Mar 31 2017
Thanks for the detailed log. It is very helpful. Updated my CL to fix the race by making DeviceSettingsService to defer its loads until InitOwner is called, which happens after private key is loaded. This is because many code that observes the ownership change signal assumes the private key is available, especially in DeviceSettingsProvider that has cached changes to write to owner settings.
,
Apr 4 2017
(marking as M-58 since it is desirable to have it ; it is breaking automated tests for ARC.)
,
Apr 4 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/c8310bb706ce377ab64aac321f6e8f286826b360 commit c8310bb706ce377ab64aac321f6e8f286826b360 Author: xiyuan <xiyuan@chromium.org> Date: Tue Apr 04 21:05:39 2017 cros: Fix flaky owner detection When owner key is generated for a consumer owner, OwnerKeySet is called on both DeviceSettingsService and OwnerSettingsServiceChromeOS. Code that watches for ownership signal from DeviceSettingsService (either as an observer or via NOTIFICATION_OWNERSHIP_STATUS_CHANGED) also expects that the private part of the owner is available at the time the signal is generated. However, the private key loading in OwnerSettingsServiceChromeOS is independent of load operations in DeviceSettingsService. The private key may or may not be loaded when a load operation finishes. The CL adds an explicit flag about whether a consumer ownership is going to be established. When the flag is set, DeviceSettingsService defers all loads until InitOwner is called, which happens when the private key is loaded. Another problem is that a bool flag |is_current_user_owner_| is used but it is not updated when switching active user. This causes incorrect value returned for IsCurrentUserOwner call. The CL fixes the problems by replacing the bool flag with comparing active user AccountId with owner AccountId. Security is not reduced because the owner account id is part of the signed policy blob and only set to UserManager after policy blob is validated. BUG= 702308 , 706820 TEST=DeviceSettingsServiceTest.LoadDeferredDuringOwnershipEastablishment Review-Url: https://codereview.chromium.org/2779973007 Cr-Commit-Position: refs/heads/master@{#461835} [modify] https://crrev.com/c8310bb706ce377ab64aac321f6e8f286826b360/chrome/browser/chromeos/login/existing_user_controller.cc [modify] https://crrev.com/c8310bb706ce377ab64aac321f6e8f286826b360/chrome/browser/chromeos/login/users/chrome_user_manager_impl.cc [modify] https://crrev.com/c8310bb706ce377ab64aac321f6e8f286826b360/chrome/browser/chromeos/login/users/chrome_user_manager_impl.h [modify] https://crrev.com/c8310bb706ce377ab64aac321f6e8f286826b360/chrome/browser/chromeos/settings/device_settings_service.cc [modify] https://crrev.com/c8310bb706ce377ab64aac321f6e8f286826b360/chrome/browser/chromeos/settings/device_settings_service.h [modify] https://crrev.com/c8310bb706ce377ab64aac321f6e8f286826b360/chrome/browser/chromeos/settings/device_settings_service_unittest.cc [modify] https://crrev.com/c8310bb706ce377ab64aac321f6e8f286826b360/components/user_manager/user_manager_base.cc [modify] https://crrev.com/c8310bb706ce377ab64aac321f6e8f286826b360/components/user_manager/user_manager_base.h
,
Apr 5 2017
hi, I noticed on https://codereview.chromium.org/2761353003 that owner_settings_service_chromeos.cc calls crypto::GetPrivateSlotForChromeOSUser without specifying a callback to wait for the slot initialization. AFAICT it is assuming that waiting on NOTIFICATION_PROFILE_CREATED and TPMTokenLoader::Get()->IsTPMTokenEnabled is sufficient, but I don't think there is any guarantee that is true. Does that sound relevant to this bug, or do you think that should be filed separately?
,
Apr 5 2017
It would definitely be one of the contribution factors. The bug happens when the DeviceSettingsService finishes a load operation and flips the ownership status before OwnerSettingsServiceChromeOS finishes loading the private key. The fix is make DeviceSettingsService defer the load operations until OwnerSettingsServiceChromeOS calls back. I had to use an explicit signal to only do that for consumer ownership establishment because I could not use existing states to differentiate policy key change or owner key gen in OwnerKeySet. The racy should be fixed by the CL though. Let's file a new bug to fix GetPrivateSlotForChromeOSUser call.
,
Apr 5 2017
Okay, I filed issue 708823 for that. Not sure what component to put it in.
,
Apr 6 2017
,
Apr 6 2017
Your change meets the bar and is auto-approved for M58. Please go ahead and merge the CL to branch 3029 manually. Please contact milestone owner if you have questions. Owners: amineer@(Android), cmasso@(iOS), bhthompson@(ChromeOS), govind@(Desktop) For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
,
Apr 6 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/33ef6173cda18bb0e9bf1d890318216b59483207 commit 33ef6173cda18bb0e9bf1d890318216b59483207 Author: Xiyuan Xia <xiyuan@google.com> Date: Thu Apr 06 15:57:34 2017 Merge "cros: Fix flaky owner detection" > When owner key is generated for a consumer owner, OwnerKeySet is > called on both DeviceSettingsService and OwnerSettingsServiceChromeOS. > Code that watches for ownership signal from DeviceSettingsService > (either as an observer or via NOTIFICATION_OWNERSHIP_STATUS_CHANGED) > also expects that the private part of the owner is available at the > time the signal is generated. However, the private key loading > in OwnerSettingsServiceChromeOS is independent of load operations > in DeviceSettingsService. The private key may or may not be loaded > when a load operation finishes. The CL adds an explicit flag about > whether a consumer ownership is going to be established. When the > flag is set, DeviceSettingsService defers all loads until InitOwner > is called, which happens when the private key is loaded. > > Another problem is that a bool flag |is_current_user_owner_| is > used but it is not updated when switching active user. This causes > incorrect value returned for IsCurrentUserOwner call. The CL fixes > the problems by replacing the bool flag with comparing active user > AccountId with owner AccountId. Security is not reduced because the > owner account id is part of the signed policy blob and only set to > UserManager after policy blob is validated. > > BUG= 702308 , 706820 > TEST=DeviceSettingsServiceTest.LoadDeferredDuringOwnershipEastablishment > > Review-Url: https://codereview.chromium.org/2779973007 > Cr-Commit-Position: refs/heads/master@{#461835} > (cherry picked from commit c8310bb706ce377ab64aac321f6e8f286826b360) Review-Url: https://codereview.chromium.org/2798343003 . Cr-Commit-Position: refs/branch-heads/3029@{#606} Cr-Branched-From: 939b32ee5ba05c396eef3fd992822fcca9a2e262-refs/heads/master@{#454471} [modify] https://crrev.com/33ef6173cda18bb0e9bf1d890318216b59483207/chrome/browser/chromeos/login/existing_user_controller.cc [modify] https://crrev.com/33ef6173cda18bb0e9bf1d890318216b59483207/chrome/browser/chromeos/login/users/chrome_user_manager_impl.cc [modify] https://crrev.com/33ef6173cda18bb0e9bf1d890318216b59483207/chrome/browser/chromeos/login/users/chrome_user_manager_impl.h [modify] https://crrev.com/33ef6173cda18bb0e9bf1d890318216b59483207/chrome/browser/chromeos/settings/device_settings_service.cc [modify] https://crrev.com/33ef6173cda18bb0e9bf1d890318216b59483207/chrome/browser/chromeos/settings/device_settings_service.h [modify] https://crrev.com/33ef6173cda18bb0e9bf1d890318216b59483207/chrome/browser/chromeos/settings/device_settings_service_unittest.cc [modify] https://crrev.com/33ef6173cda18bb0e9bf1d890318216b59483207/components/user_manager/user_manager_base.cc [modify] https://crrev.com/33ef6173cda18bb0e9bf1d890318216b59483207/components/user_manager/user_manager_base.h
,
Apr 6 2017
,
May 11 2017
|
|||||||||
►
Sign in to add a comment |
|||||||||
Comment 1 by kinaba@chromium.org
, Mar 30 2017