Add UMA for consistency between TPM and install attributes.

chrome/browser/chromeos/policy/enterprise_install_attributes.cc

Index: chrome/browser/chromeos/policy/enterprise_install_attributes.cc
diff --git a/chrome/browser/chromeos/policy/enterprise_install_attributes.cc b/chrome/browser/chromeos/policy/enterprise_install_attributes.cc
index 3fbbc8d00d2e38def39a61379e44f1b2625da2e1..11af1d2c03aa1f6abe7edc2541ac783aa682d19b 100644
--- a/chrome/browser/chromeos/policy/enterprise_install_attributes.cc
+++ b/chrome/browser/chromeos/policy/enterprise_install_attributes.cc
@@ -11,6 +11,9 @@
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/message_loop/message_loop.h"
+#include "base/metrics/histogram_base.h"
+#include "base/metrics/histogram_macros.h"
+#include "base/time/time.h"
 #include "chrome/browser/chromeos/policy/proto/install_attributes.pb.h"
 #include "chromeos/cryptohome/cryptohome_util.h"
 #include "chromeos/dbus/dbus_thread_manager.h"
@@ -22,6 +25,12 @@ namespace cryptohome_util = chromeos::cryptohome_util;
 
 namespace {
 
+// Retry interval for consistency check against TPM lock state.
+int kDbusRetryIntervalInSeconds = 5;
+
+// Total time during which of TPM lock state queries are retried.
+int kDbusRetryDurationInSeconds = 60;
+
 bool ReadMapKey(const std::map<std::string, std::string>& map,
                 const std::string& key,
                 std::string* value) {
@@ -56,6 +65,7 @@ EnterpriseInstallAttributes::GetEnterpriseOwnedInstallAttributesBlobForTesting(
 EnterpriseInstallAttributes::EnterpriseInstallAttributes(
     chromeos::CryptohomeClient* cryptohome_client)
     : device_locked_(false),
+      consistency_check_running_(false),
       registration_mode_(DEVICE_MODE_PENDING),
       cryptohome_client_(cryptohome_client),
       weak_ptr_factory_(this) {
@@ -63,9 +73,15 @@ EnterpriseInstallAttributes::EnterpriseInstallAttributes(
 
 EnterpriseInstallAttributes::~EnterpriseInstallAttributes() {}
 
-void EnterpriseInstallAttributes::ReadCacheFile(
-    const base::FilePath& cache_file) {
-  if (device_locked_ || !base::PathExists(cache_file))
+void EnterpriseInstallAttributes::Init(const base::FilePath& cache_file) {
+  DCHECK_EQ(false, device_locked_);
+
+  // The actual check happens asynchronously, thus it is ok to trigger it before
+  // Init() has completed.
+  TriggerConsistencyCheck(
+      kDbusRetryDurationInSeconds / kDbusRetryIntervalInSeconds);

[Mattias Nissler (ping if slow), 2015/06/24 08:34:39]

Why not just a number-of-retries constant?

[Thiemo Nagel, 2015/06/24 10:43:36]

I think it is easier to reason about retries in terms of retry interval and
retry duration.  If I'd specify retry interval and retry count, readers of the
code would automatically multiply the two in their head, causing unnecessary
load.

[Mattias Nissler (ping if slow), 2015/06/24 11:55:03]

I found myself doing the exact inverse of what you described, i.e. doing the
division in my brain to find out the total number of attempts :)

So maybe this is just depends on who is reading. Given that multiplication is
the simpler operation and the fact number-of-attempts constants are more common
in the code base in my experience, I think we should still go with that.

[Thiemo Nagel, 2015/06/24 12:49:52]

Done.

+
+  if (!base::PathExists(cache_file))
     return;
 
   device_locked_ = true;
@@ -186,6 +202,19 @@ void EnterpriseInstallAttributes::LockDevice(
     return;
   }
 
+  // In case the consistency check is still running, postpone the device locking
+  // until it has finished.  This should not introduce additional delay since
+  // device locking must wait for TPM initialization as well.
+  if (consistency_check_running_) {
+    post_check_action_ = base::Bind(&EnterpriseInstallAttributes::LockDevice,

[Mattias Nissler (ping if slow), 2015/06/24 08:34:39]

So in theory this opens up an error condition where |callback| never gets
invoked because somebody calls LockDevice twice in a row (the second call will
clobber the first |post_check_action_|).

I don't think the code is prepared to handle multiple concurrent LockDevice
calls anyways. However, instead of compounding the problem, we might just as
well fix this? We could just reject further LockDevice calls when one is still
ongoing.

For background, I think this whole issue with multiple concurrently LockDevices
calls slipped in the review when people started converting the stuff in this
class to make async DBus calls.

[Thiemo Nagel, 2015/06/24 10:43:36]

Sounds good.  Done.

+                                    weak_ptr_factory_.GetWeakPtr(),
+                                    user,
+                                    device_mode,
+                                    device_id,
+                                    callback);
+    return;
+  }
+
   cryptohome_client_->InstallAttributesIsReady(
       base::Bind(&EnterpriseInstallAttributes::LockDeviceIfAttributesIsReady,
                  weak_ptr_factory_.GetWeakPtr(),
@@ -318,6 +347,45 @@ DeviceMode EnterpriseInstallAttributes::GetMode() {
   return registration_mode_;
 }
 
+void EnterpriseInstallAttributes::TriggerConsistencyCheck(
+    int dbus_tries_remaining) {
+  consistency_check_running_ = true;
+  cryptohome_client_->TpmIsOwned(base::Bind(
+      &EnterpriseInstallAttributes::OnTpmIsOwned,
+      weak_ptr_factory_.GetWeakPtr(),
+      dbus_tries_remaining));
+}
+
+void EnterpriseInstallAttributes::OnTpmIsOwned(
+    int dbus_tries_remaining,
+    chromeos::DBusMethodCallStatus call_status,
+    bool result) {
+  if (call_status != chromeos::DBUS_METHOD_CALL_SUCCESS &&
+      dbus_tries_remaining) {
+    base::MessageLoop::current()->PostDelayedTask(
+        FROM_HERE,
+        base::Bind(&EnterpriseInstallAttributes::TriggerConsistencyCheck,
+                   weak_ptr_factory_.GetWeakPtr(),
+                   dbus_tries_remaining - 1),
+        base::TimeDelta::FromSeconds(kDbusRetryIntervalInSeconds));
+    return;
+  }
+
+  base::HistogramBase::Sample state = device_locked_;
+  state |= 0x2 * (registration_mode_ == DEVICE_MODE_ENTERPRISE);
+  if (call_status == chromeos::DBUS_METHOD_CALL_SUCCESS)
+    state |= 0x4 * result;
+  else
+    state |= 0x8;

[Mattias Nissler (ping if slow), 2015/06/24 08:34:39]

Think more about this bitset - does it make sense to encode the error condition
as a bit? |result| is missing in that case, which means that the data point is
pretty much useless anyways.

I think your motivation is to catch cases where the consistency check fails to
determine TPM ownership status. Wouldn't that sufficiently be covered by a
separate UMA stat that captures the relative error frequency? That way, you
would avoid to double the space of possible values for the state histogram.

[Thiemo Nagel, 2015/06/24 10:43:36]

If the TPM check fails, there's something amiss, and I'd like to obtain as much
information as possible for that case.  It might be interesting to know whether
the failure is related to the install attributes state.  For that reason, I'm
compounding all results in a single enum.

[Mattias Nissler (ping if slow), 2015/06/24 11:55:03]

I don't think the install attributes state bit gives you much relevant
information to debug this situtation though. The bit is generated by
mount-encrypted and lockbox-cache during startup, however you'd need to start
digging on the cryptohomed side to find out why these calls fail consistently,
and cryptohomed contains completely separate code for handling install
attributes. Given that, I don't think it's worth to complicate the UMA histogram
here - I think the benefit of keeping the histogram at 8 easy-to understand
values for casual inspectors and future maintainers is more beneficial than the
hypothetical benefit that install attributes state bit in case of error
provides.

Regardless of that, the enterprise mode bit and the tpm-is-owned bit are totally
irrelevant in case of error, so even if you want to keep track of install
attributes state in presence of an error, a better way would be to create a
separate histogram that just records the pair install attributes state and
error-occurred bits.

[Thiemo Nagel, 2015/06/24 12:49:52]

Alright.  I've condensed the 4 error cases into a single one, but I'd prefer to
keep it in the same histogram to prevent it from being overlooked and also to
avoid the overhead of creating, maintaining and looking at yet another
histogram.

[Mattias Nissler (ping if slow), 2015/06/24 13:26:06]

I don't see how a separate would introduce significant additional maintenance
overhead, but the point about the error condition being present in the original
histogram being beneficial makes sense to me.

[Thiemo Nagel, 2015/06/24 14:05:39]

Basically, it pollutes the namespace.  Scrolling through Enterprise.* metrics
takes longer without adding any value.  Looking at two histograms takes longer
than looking at one histogram (two dremel queries instead of one).

[Mattias Nissler (ping if slow), 2015/06/24 18:37:10]

I agree with these, although I would personally consider these points of
negligible relevance ;) My point was meant to be about code maintenance. Sorry
for not being entirely clear.

[Thiemo Nagel, 2015/06/25 09:04:06]

I wasn't entirely clear, either.  I think my point applies more to a casual
reader than to someone with a deep understanding of this part of the codebase.

+  UMA_HISTOGRAM_ENUMERATION("Enterprise.AttributesTPMConsistency", state, 12);
+
+  // Run any action (LockDevice call) that might have queued behind the
+  // consistency check.
+  consistency_check_running_ = false;
+  if (!post_check_action_.is_null())
+    post_check_action_.Run();
+}
+
 // Warning: The values for these keys (but not the keys themselves) are stored
 // in the protobuf with a trailing zero.  Also note that some of these constants
 // have been copied to login_manager/device_policy_service.cc.  Please make sure