chromeos: Avoid cryptohome D-Bus log spam at boot.

chromeos: Avoid cryptohome D-Bus log spam at boot.

Make EnterpriseInstallAttributes defer running its
consistency check (which calls cryptohome's TpmIsOwned
method over D-Bus) until the cryptohome service is
available.

Also fix an apparent bug where the check was retried five
times the intended number of times.

BUG=636554
Committed: https://crrev.com/8f07351eab26e3b2d49fd4aa3c81f19e9656d6c2
Cr-Commit-Position: refs/heads/master@{#419180}

[Daniel Erat, 2016-08-11 21:34:42]

derat@chromium.org changed reviewers:
+ tnagel@chromium.org

[Daniel Erat, 2016-08-11 21:34:43]

https://codereview.chromium.org/2244443002/diff/1/chrome/browser/chromeos/pol...
File chrome/browser/chromeos/policy/enterprise_install_attributes.cc (left):

https://codereview.chromium.org/2244443002/diff/1/chrome/browser/chromeos/pol...
chrome/browser/chromeos/policy/enterprise_install_attributes.cc:86:
TriggerConsistencyCheck(kDbusRetryCount * kDbusRetryIntervalInSeconds);
the multiplication by kDbusRetryIntervalInSeconds looks like a bug to me. the
method has the following signature:

  void EnterpriseInstallAttributes::TriggerConsistencyCheck(int dbus_retries)

and the argument indeed appears to be passed through to the callback as the
remaining number of retries. i don't see any reason for it to be multiplied by
the interval.

https://codereview.chromium.org/2244443002/diff/1/chrome/browser/chromeos/pol...
File chrome/browser/chromeos/policy/enterprise_install_attributes.cc (right):

https://codereview.chromium.org/2244443002/diff/1/chrome/browser/chromeos/pol...
chrome/browser/chromeos/policy/enterprise_install_attributes.cc:435:
TriggerConsistencyCheck(kDbusRetryCount);
calling this asynchronously when the service becomes available instead of
synchronously from Init() may have unintended consequences:

- TriggerConsistencyCheck() sets consistency_check_running_ to true
- LockDevice() defers locking if consistency_check_running_ is true

therefore, now that the running_ member is set to true asynchronously instead of
within Init(), there may be a possibility that LockDevice() could run before the
consistency check starts. when cryptohome later becomes available,
TriggerConsistencyCheck() might run while the device is in the process of being
locked.

LockDevice() appears to assume that cryptohome is ready, though (it calls
CryptohomeClient::InstallAttributesIsReady()), so perhaps it is only run much
later in response to a user action, long after cryptohome has become available
and the consistency check has started.

if the consistency check needs to run first, however, i could make Init()
synchronously set consistency_check_running_ to true and just defer the
consistency check's d-bus calls until the service is available. that way,
LockDevice() would continue to be blocked until the consistency check has run.

that might lead to slightly trickier code, though. let me know what you'd
prefer.

[Daniel Erat, 2016-08-11 21:46:45]

The CQ bit was checked by derat@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-08-11 21:47:37]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-08-11 22:47:10]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-08-11 22:47:14]

Dry run: Try jobs failed on following builders:
  linux_chromium_chromeos_rel_ng on master.tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_chromium_...)

[Thiemo Nagel, 2016-08-12 13:06:17]

I'll hold back reviewing this until we're both back from vacation.  (Please ping
me in case I forget.)

[Daniel Erat, 2016-08-31 16:03:30]

The CQ bit was checked by derat@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-08-31 16:04:22]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-08-31 16:58:39]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-08-31 16:58:42]

Dry run: This issue passed the CQ dry run.

[Daniel Erat, 2016-09-07 17:36:35]

looks like we're both around now. mind taking a look at this?

[Mattias Nissler (ping if slow), 2016-09-07 19:47:24]

mnissler@chromium.org changed reviewers:
+ mnissler@chromium.org

[Mattias Nissler (ping if slow), 2016-09-07 19:47:25]

Spring cleaning? I like it! ;-)

LGTM w/ nits but I no longer have powers in this strange enterprise land...

https://codereview.chromium.org/2244443002/diff/1/chrome/browser/chromeos/pol...
File chrome/browser/chromeos/policy/enterprise_install_attributes.cc (left):

https://codereview.chromium.org/2244443002/diff/1/chrome/browser/chromeos/pol...
chrome/browser/chromeos/policy/enterprise_install_attributes.cc:86:
TriggerConsistencyCheck(kDbusRetryCount * kDbusRetryIntervalInSeconds);
On 2016/08/11 21:34:43, Daniel Erat wrote:
> the multiplication by kDbusRetryIntervalInSeconds looks like a bug to me. the
> method has the following signature:
> 
>   void EnterpriseInstallAttributes::TriggerConsistencyCheck(int dbus_retries)
> 
> and the argument indeed appears to be passed through to the callback as the
> remaining number of retries. i don't see any reason for it to be multiplied by
> the interval.

Agreed.

https://codereview.chromium.org/2244443002/diff/1/chrome/browser/chromeos/pol...
File chrome/browser/chromeos/policy/enterprise_install_attributes.cc (right):

https://codereview.chromium.org/2244443002/diff/1/chrome/browser/chromeos/pol...
chrome/browser/chromeos/policy/enterprise_install_attributes.cc:435:
TriggerConsistencyCheck(kDbusRetryCount);
On 2016/08/11 21:34:43, Daniel Erat wrote:
> calling this asynchronously when the service becomes available instead of
> synchronously from Init() may have unintended consequences:
> 
> - TriggerConsistencyCheck() sets consistency_check_running_ to true
> - LockDevice() defers locking if consistency_check_running_ is true
> 
> therefore, now that the running_ member is set to true asynchronously instead
of
> within Init(), there may be a possibility that LockDevice() could run before
the
> consistency check starts. when cryptohome later becomes available,
> TriggerConsistencyCheck() might run while the device is in the process of
being
> locked.
> 
> LockDevice() appears to assume that cryptohome is ready, though (it calls
> CryptohomeClient::InstallAttributesIsReady()), so perhaps it is only run much
> later in response to a user action, long after cryptohome has become available
> and the consistency check has started.
> 
> if the consistency check needs to run first, however, i could make Init()
> synchronously set consistency_check_running_ to true and just defer the
> consistency check's d-bus calls until the service is available. that way,
> LockDevice() would continue to be blocked until the consistency check has run.
> 
> that might lead to slightly trickier code, though. let me know what you'd
> prefer.

I'd just set consistency_check_running_ to true in Init() - better safe than
sorry regarding sequencing of operations, since we've seen TPM initialization
taking minutes (!) on some devices. I don't think the code would become
significantly more tricky that way.

[Daniel Erat, 2016-09-07 20:46:52]

https://codereview.chromium.org/2244443002/diff/1/chrome/browser/chromeos/pol...
File chrome/browser/chromeos/policy/enterprise_install_attributes.cc (left):

https://codereview.chromium.org/2244443002/diff/1/chrome/browser/chromeos/pol...
chrome/browser/chromeos/policy/enterprise_install_attributes.cc:86:
TriggerConsistencyCheck(kDbusRetryCount * kDbusRetryIntervalInSeconds);
On 2016/09/07 19:47:24, Mattias Nissler (ping if slow) wrote:
> On 2016/08/11 21:34:43, Daniel Erat wrote:
> > the multiplication by kDbusRetryIntervalInSeconds looks like a bug to me.
the
> > method has the following signature:
> > 
> >   void EnterpriseInstallAttributes::TriggerConsistencyCheck(int
dbus_retries)
> > 
> > and the argument indeed appears to be passed through to the callback as the
> > remaining number of retries. i don't see any reason for it to be multiplied
by
> > the interval.
> 
> Agreed.

Acknowledged.

https://codereview.chromium.org/2244443002/diff/1/chrome/browser/chromeos/pol...
File chrome/browser/chromeos/policy/enterprise_install_attributes.cc (right):

https://codereview.chromium.org/2244443002/diff/1/chrome/browser/chromeos/pol...
chrome/browser/chromeos/policy/enterprise_install_attributes.cc:435:
TriggerConsistencyCheck(kDbusRetryCount);
On 2016/09/07 19:47:25, Mattias Nissler (ping if slow) wrote:
> On 2016/08/11 21:34:43, Daniel Erat wrote:
> > calling this asynchronously when the service becomes available instead of
> > synchronously from Init() may have unintended consequences:
> > 
> > - TriggerConsistencyCheck() sets consistency_check_running_ to true
> > - LockDevice() defers locking if consistency_check_running_ is true
> > 
> > therefore, now that the running_ member is set to true asynchronously
instead
> of
> > within Init(), there may be a possibility that LockDevice() could run before
> the
> > consistency check starts. when cryptohome later becomes available,
> > TriggerConsistencyCheck() might run while the device is in the process of
> being
> > locked.
> > 
> > LockDevice() appears to assume that cryptohome is ready, though (it calls
> > CryptohomeClient::InstallAttributesIsReady()), so perhaps it is only run
much
> > later in response to a user action, long after cryptohome has become
available
> > and the consistency check has started.
> > 
> > if the consistency check needs to run first, however, i could make Init()
> > synchronously set consistency_check_running_ to true and just defer the
> > consistency check's d-bus calls until the service is available. that way,
> > LockDevice() would continue to be blocked until the consistency check has
run.
> > 
> > that might lead to slightly trickier code, though. let me know what you'd
> > prefer.
> 
> I'd just set consistency_check_running_ to true in Init() - better safe than
> sorry regarding sequencing of operations, since we've seen TPM initialization
> taking minutes (!) on some devices. I don't think the code would become
> significantly more tricky that way.

Done.

[Daniel Erat, 2016-09-07 20:48:01]

The CQ bit was checked by derat@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-09-07 20:48:29]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-09-07 21:39:36]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-09-07 21:39:37]

Dry run: This issue passed the CQ dry run.

[Daniel Erat, 2016-09-15 16:26:23]

thiemo, have you had a chance to take a look at this yet?

[Thiemo Nagel, 2016-09-16 03:22:06]

LGTM.  (Sorry this took so long.  I'm still traveling.)

https://codereview.chromium.org/2244443002/diff/20001/chrome/browser/chromeos...
File chrome/browser/chromeos/policy/enterprise_install_attributes.cc (right):

https://codereview.chromium.org/2244443002/diff/20001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/enterprise_install_attributes.cc:427: LOG(ERROR)
<< "Failed waiting for cryptohome D-Bus service availability";
Nit: I'd suggest ending sentence with a period.

[Thiemo Nagel, 2016-09-16 05:42:18]

Thinking a bit more about this: Could it contain a race condition?  When
cryptohome comes up faster than Chrome, will
OnCryptohomeServiceInitiallyAvailable() still be called?

[Mattias Nissler (ping if slow), 2016-09-16 07:30:26]

On 2016/09/16 05:42:18, Thiemo Nagel (slow) wrote:
> Thinking a bit more about this: Could it contain a race condition?  When
> cryptohome comes up faster than Chrome, will
> OnCryptohomeServiceInitiallyAvailable() still be called?

According to
https://cs.chromium.org/chromium/src/dbus/object_proxy.cc?rcl=1473995854&l=453
there'll be an immediate callback for the case where the service is already
available.

[Daniel Erat, 2016-09-16 15:25:36]

On 2016/09/16 07:30:26, Mattias Nissler (ping if slow) wrote:
> On 2016/09/16 05:42:18, Thiemo Nagel (slow) wrote:
> > Thinking a bit more about this: Could it contain a race condition?  When
> > cryptohome comes up faster than Chrome, will
> > OnCryptohomeServiceInitiallyAvailable() still be called?
> 
> According to
> https://cs.chromium.org/chromium/src/dbus/object_proxy.cc?rcl=1473995854&l=453
> there'll be an immediate callback for the case where the service is already
> available.

yes, this is documented in dbus::ObjectProxy:

  // Registers |callback| to run when the service becomes available. If the
  // service is already available, or if connecting to the name-owner-changed
  // signal fails, |callback| will be run once asynchronously. Otherwise,
  // |callback| will be run once in the future after the service becomes
  // available.
  virtual void WaitForServiceToBeAvailable(
      WaitForServiceToBeAvailableCallback callback);

[Daniel Erat, 2016-09-16 15:25:51]

https://codereview.chromium.org/2244443002/diff/20001/chrome/browser/chromeos...
File chrome/browser/chromeos/policy/enterprise_install_attributes.cc (right):

https://codereview.chromium.org/2244443002/diff/20001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/enterprise_install_attributes.cc:427: LOG(ERROR)
<< "Failed waiting for cryptohome D-Bus service availability";
On 2016/09/16 03:22:06, Thiemo Nagel (slow) wrote:
> Nit: I'd suggest ending sentence with a period.

chrome appears to lean slightly more in the direction of omitting trailing
periods in error messages, but i'll update this to match the rest of the file
(and update the one place where the file was inconsistent). :-)

% git grep 'LOG(ERROR).*\.";' | wc -l
1545
% git grep 'LOG(ERROR).*[^.]";' | wc -l
2184

[Daniel Erat, 2016-09-16 15:25:59]

The CQ bit was checked by derat@chromium.org

[Daniel Erat, 2016-09-16 15:25:59]

The patchset sent to the CQ was uploaded after l-g-t-m from
mnissler@chromium.org, tnagel@chromium.org
Link to the patchset: https://codereview.chromium.org/2244443002/#ps40001
(title: "add trailing period")

[commit-bot: I haz the power, 2016-09-16 15:26:19]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-09-16 16:07:09]

Committed patchset #3 (id:40001)

[commit-bot: I haz the power, 2016-09-16 16:09:48]

Description was changed from

==========
chromeos: Avoid cryptohome D-Bus log spam at boot.

Make EnterpriseInstallAttributes defer running its
consistency check (which calls cryptohome's TpmIsOwned
method over D-Bus) until the cryptohome service is
available.

Also fix an apparent bug where the check was retried five
times the intended number of times.

BUG=636554
==========

to

==========
chromeos: Avoid cryptohome D-Bus log spam at boot.

Make EnterpriseInstallAttributes defer running its
consistency check (which calls cryptohome's TpmIsOwned
method over D-Bus) until the cryptohome service is
available.

Also fix an apparent bug where the check was retried five
times the intended number of times.

BUG=636554

Committed: https://crrev.com/8f07351eab26e3b2d49fd4aa3c81f19e9656d6c2
Cr-Commit-Position: refs/heads/master@{#419180}
==========

[commit-bot: I haz the power, 2016-09-16 16:09:49]

Patchset 3 (id:??) landed as
https://crrev.com/8f07351eab26e3b2d49fd4aa3c81f19e9656d6c2
Cr-Commit-Position: refs/heads/master@{#419180}