Add an extra delay for policy invalidations to be available.

The cloud policy refresh scheduler no longer waits for policy invalidations to become available before issuing the first policy fetch. We want to ensure that any policy change that results from this initial policy fetch is counted as a change without invalidations enabled for metrics purposes.

Currently we determine if invalidations are enabled based on whether the invalidation service has reported that it is on. However, there may be a delay between the invalidation service being enabled and the invalidation service actually delivering a pending invalidation. Additionally, on Android the invalidation service always reports that it is enabled. To account for this, add a "grace period" after the invalidation service is enabled during which we still consider invalidations disabled for metrics reporting.

BUG=355884

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

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

chrome/browser/policy/cloud/cloud_policy_invalidator.cc

@@ -12,6 +12,7 @@
 #include "base/rand_util.h"
 #include "base/sequenced_task_runner.h"
 #include "base/strings/string_number_conversions.h"
+#include "base/time/clock.h"
 #include "base/time/time.h"
 #include "base/values.h"
 #include "chrome/browser/invalidation/invalidation_service.h"
@@ -28,17 +29,20 @@ const int CloudPolicyInvalidator::kMissingPayloadDelay = 5;
 const int CloudPolicyInvalidator::kMaxFetchDelayDefault = 120000;
 const int CloudPolicyInvalidator::kMaxFetchDelayMin = 1000;
 const int CloudPolicyInvalidator::kMaxFetchDelayMax = 300000;
+const int CloudPolicyInvalidator::kInvalidationGracePeriod = 10;
 
 CloudPolicyInvalidator::CloudPolicyInvalidator(
     CloudPolicyCore* core,
-    const scoped_refptr<base::SequencedTaskRunner>& task_runner)
+    const scoped_refptr<base::SequencedTaskRunner>& task_runner,
+    scoped_ptr<base::Clock> clock)
     : state_(UNINITIALIZED),
       core_(core),
       task_runner_(task_runner),
+      clock_(clock.Pass()),
       invalidation_service_(NULL),
       invalidations_enabled_(false),
       invalidation_service_enabled_(false),
-      registered_timestamp_(0),
+      is_registered_(false),
       invalid_(false),
       invalidation_version_(0),
       unknown_version_invalidation_count_(0),
@@ -69,7 +73,7 @@ void CloudPolicyInvalidator::Shutdown() {
   DCHECK(state_ != SHUT_DOWN);
   DCHECK(thread_checker_.CalledOnValidThread());
   if (state_ == STARTED) {
-    if (registered_timestamp_)
+    if (is_registered_)
       invalidation_service_->UnregisterInvalidationHandler(this);
     core_->store()->RemoveObserver(this);
     weak_factory_.InvalidateWeakPtrs();
@@ -137,19 +141,12 @@ void CloudPolicyInvalidator::OnStoreLoaded(CloudPolicyStore* store) {
   DCHECK(thread_checker_.CalledOnValidThread());
   bool policy_changed = IsPolicyChanged(store->policy());
 
-  if (registered_timestamp_) {
-    // Update the kMetricPolicyRefresh histogram. In some cases, this object can
-    // be constructed during an OnStoreLoaded callback, which causes
-    // OnStoreLoaded to be called twice at initialization time, so make sure
-    // that the timestamp does not match the timestamp at which registration
-    // occurred. We only measure changes which occur after registration.
-    if (!store->policy() || !store->policy()->has_timestamp() ||
-        store->policy()->timestamp() != registered_timestamp_) {
-      UMA_HISTOGRAM_ENUMERATION(
-          kMetricPolicyRefresh,
-          GetPolicyRefreshMetric(policy_changed),
-          METRIC_POLICY_REFRESH_SIZE);
-    }
+  if (is_registered_) {
+    // Update the kMetricPolicyRefresh histogram.
+    UMA_HISTOGRAM_ENUMERATION(
+        kMetricPolicyRefresh,
+        GetPolicyRefreshMetric(policy_changed),
+        METRIC_POLICY_REFRESH_SIZE);
 
     // If the policy was invalid and the version stored matches the latest
     // invalidation version, acknowledge the latest invalidation.
@@ -229,7 +226,6 @@ void CloudPolicyInvalidator::UpdateRegistration(
   // Create the ObjectId based on the policy data.
   // If the policy does not specify an the ObjectId, then unregister.
   if (!policy ||
-      !policy->has_timestamp() ||
       !policy->has_invalidation_source() ||
       !policy->has_invalidation_name()) {
     Unregister();
@@ -241,15 +237,13 @@ void CloudPolicyInvalidator::UpdateRegistration(
 
   // If the policy object id in the policy data is different from the currently
   // registered object id, update the object registration.
-  if (!registered_timestamp_ || !(object_id == object_id_))
-    Register(policy->timestamp(), object_id);
+  if (!is_registered_ || !(object_id == object_id_))
+    Register(object_id);
 }
 
-void CloudPolicyInvalidator::Register(
-    int64 timestamp,
-    const invalidation::ObjectId& object_id) {
+void CloudPolicyInvalidator::Register(const invalidation::ObjectId& object_id) {
   // Register this handler with the invalidation service if needed.
-  if (!registered_timestamp_) {
+  if (!is_registered_) {
     OnInvalidatorStateChange(invalidation_service_->GetInvalidatorState());
     invalidation_service_->RegisterInvalidationHandler(this);
   }
@@ -257,7 +251,7 @@ void CloudPolicyInvalidator::Register(
   // Update internal state.
   if (invalid_)
     AcknowledgeInvalidation();
-  registered_timestamp_ = timestamp;
+  is_registered_ = true;
   object_id_ = object_id;
   UpdateInvalidationsEnabled();
 
@@ -268,14 +262,14 @@ void CloudPolicyInvalidator::Register(
 }
 
 void CloudPolicyInvalidator::Unregister() {
-  if (registered_timestamp_) {
+  if (is_registered_) {
     if (invalid_)
       AcknowledgeInvalidation();
     invalidation_service_->UpdateRegisteredInvalidationIds(
         this,
         syncer::ObjectIdSet());
     invalidation_service_->UnregisterInvalidationHandler(this);
-    registered_timestamp_ = 0;
+    is_registered_ = false;
     UpdateInvalidationsEnabled();
   }
 }
@@ -313,10 +307,11 @@ void CloudPolicyInvalidator::set_max_fetch_delay(int delay) {
 }
 
 void CloudPolicyInvalidator::UpdateInvalidationsEnabled() {
-  bool invalidations_enabled =
-      invalidation_service_enabled_ && registered_timestamp_;
+  bool invalidations_enabled = invalidation_service_enabled_ && is_registered_;
   if (invalidations_enabled_ != invalidations_enabled) {
     invalidations_enabled_ = invalidations_enabled;
+    if (invalidations_enabled)
+      invalidations_enabled_time_ = clock_->Now();
     core_->refresh_scheduler()->SetInvalidationServiceAvailability(
         invalidations_enabled);
   }
@@ -357,7 +352,7 @@ int CloudPolicyInvalidator::GetPolicyRefreshMetric(bool policy_changed) {
   if (policy_changed) {
     if (invalid_)
       return METRIC_POLICY_REFRESH_INVALIDATED_CHANGED;
-    if (invalidations_enabled_)
+    if (GetInvalidationsEnabled())
       return METRIC_POLICY_REFRESH_CHANGED;
     return METRIC_POLICY_REFRESH_CHANGED_NO_INVALIDATIONS;
   }
@@ -366,4 +361,13 @@ int CloudPolicyInvalidator::GetPolicyRefreshMetric(bool policy_changed) {
   return METRIC_POLICY_REFRESH_UNCHANGED;
 }
 
+bool CloudPolicyInvalidator::GetInvalidationsEnabled() {
+  if (!invalidations_enabled_)
+    return false;
+  // If invalidations have been enabled for less than the grace period, then
+  // consider invalidations to be disabled for metrics reporting.
+  base::TimeDelta elapsed = clock_->Now() - invalidations_enabled_time_;
+  return elapsed.InSeconds() >= kInvalidationGracePeriod;
+}
+
 }  // namespace policy

chrome/browser/policy/cloud/cloud_policy_invalidator.h

@@ -20,6 +20,7 @@
 #include "sync/notifier/invalidation_handler.h"
 
 namespace base {
+class Clock;
 class SequencedTaskRunner;
 }
 
@@ -43,13 +44,19 @@ class CloudPolicyInvalidator : public syncer::InvalidationHandler,
   static const int kMaxFetchDelayMin;
   static const int kMaxFetchDelayMax;
 
+  // The grace period, in seconds, to allow for invalidations to be received
+  // once the invalidation service starts up.
+  static const int kInvalidationGracePeriod;
+
   // |core| is the cloud policy core which connects the various policy objects.
   // It must remain valid until Shutdown is called.
   // |task_runner| is used for scheduling delayed tasks. It must post tasks to
   // the main policy thread.
+  // |clock| is used to get the current time.
   CloudPolicyInvalidator(
       CloudPolicyCore* core,
-      const scoped_refptr<base::SequencedTaskRunner>& task_runner);
+      const scoped_refptr<base::SequencedTaskRunner>& task_runner,
+      scoped_ptr<base::Clock> clock);
   virtual ~CloudPolicyInvalidator();
 
   // Initializes the invalidator. No invalidations will be generated before this
@@ -92,7 +99,7 @@ class CloudPolicyInvalidator : public syncer::InvalidationHandler,
   void UpdateRegistration(const enterprise_management::PolicyData* policy);
 
   // Registers the given object with the invalidation service.
-  void Register(int64 timestamp, const invalidation::ObjectId& object_id);
+  void Register(const invalidation::ObjectId& object_id);
 
   // Unregisters the current object with the invalidation service.
   void Unregister();
@@ -121,6 +128,9 @@ class CloudPolicyInvalidator : public syncer::InvalidationHandler,
   // when a policy is stored.
   int GetPolicyRefreshMetric(bool policy_changed);
 
+  // Determine if invalidations have been enabled longer than the grace period.
+  bool GetInvalidationsEnabled();
+
   // The state of the object.
   enum State {
     UNINITIALIZED,
@@ -136,6 +146,9 @@ class CloudPolicyInvalidator : public syncer::InvalidationHandler,
   // Schedules delayed tasks.
   const scoped_refptr<base::SequencedTaskRunner> task_runner_;
 
+  // The clock.
+  scoped_ptr<base::Clock> clock_;
+
   // The invalidation service.
   invalidation::InvalidationService* invalidation_service_;
 
@@ -144,12 +157,14 @@ class CloudPolicyInvalidator : public syncer::InvalidationHandler,
   // has registered for a policy object.
   bool invalidations_enabled_;
 
+  // The time that invalidations became enabled.
+  base::Time invalidations_enabled_time_;
+
   // Whether the invalidation service is currently enabled.
   bool invalidation_service_enabled_;
 
-  // The timestamp of the PolicyData at which this object registered for policy
-  // invalidations. Set to zero if the object has not registered yet.
-  int64 registered_timestamp_;
+  // Whether this object has registered for policy invalidations.
+  bool is_registered_;
 
   // The object id representing the policy in the invalidation service.
   invalidation::ObjectId object_id_;

chrome/browser/policy/cloud/cloud_policy_invalidator_unittest.cc

@@ -14,6 +14,7 @@
 #include "base/metrics/sample_map.h"
 #include "base/metrics/statistics_recorder.h"
 #include "base/run_loop.h"
+#include "base/test/simple_test_clock.h"
 #include "base/test/test_simple_task_runner.h"
 #include "base/time/time.h"
 #include "base/values.h"
@@ -147,6 +148,9 @@ class CloudPolicyInvalidatorTest : public testing::Test {
   base::HistogramBase::Count GetCount(MetricPolicyRefresh metric);
   base::HistogramBase::Count GetInvalidationCount(bool with_payload);
 
+  // Advance the test clock.
+  void AdvanceClock(base::TimeDelta delta);
+
  private:
   // Checks that the policy was refreshed due to an invalidation with the given
   // base delay.
@@ -170,6 +174,7 @@ class CloudPolicyInvalidatorTest : public testing::Test {
   CloudPolicyCore core_;
   MockCloudPolicyClient* client_;
   scoped_refptr<base::TestSimpleTaskRunner> task_runner_;
+  base::SimpleTestClock* clock_;
 
   // The invalidator which will be tested.
   scoped_ptr<CloudPolicyInvalidator> invalidator_;
@@ -203,6 +208,7 @@ CloudPolicyInvalidatorTest::CloudPolicyInvalidatorTest()
             loop_.message_loop_proxy()),
       client_(NULL),
       task_runner_(new base::TestSimpleTaskRunner()),
+      clock_(new base::SimpleTestClock()),
       object_id_a_(135, "asdf"),
       object_id_b_(246, "zxcv"),
       timestamp_(123456),
@@ -225,7 +231,10 @@ void CloudPolicyInvalidatorTest::TearDown() {
 void CloudPolicyInvalidatorTest::StartInvalidator(
     bool initialize,
     bool start_refresh_scheduler) {
-  invalidator_.reset(new CloudPolicyInvalidator(&core_, task_runner_));
+  invalidator_.reset(new CloudPolicyInvalidator(
+      &core_,
+      task_runner_,
+      scoped_ptr<base::Clock>(clock_)));
   if (start_refresh_scheduler) {
     ConnectCore();
     StartRefreshScheduler();
@@ -380,6 +389,10 @@ base::HistogramBase::Count CloudPolicyInvalidatorTest::GetInvalidationCount(
       invalidations_samples_->GetCount(metric);
 }
 
+void CloudPolicyInvalidatorTest::AdvanceClock(base::TimeDelta delta) {
+  clock_->Advance(delta);
+}
+
 bool CloudPolicyInvalidatorTest::CheckPolicyRefreshed(base::TimeDelta delay) {
   base::TimeDelta max_delay = delay + base::TimeDelta::FromMilliseconds(
       CloudPolicyInvalidator::kMaxFetchDelayMin);
@@ -776,38 +789,48 @@ TEST_F(CloudPolicyInvalidatorTest, RefreshMetricsNoInvalidations) {
   // on whether the invalidation service was enabled or not.
   StorePolicy(POLICY_OBJECT_A);
   StartInvalidator();
+
+  // Initially, invalidations have not been enabled past the grace period, so
+  // invalidations are OFF.
   StorePolicy(POLICY_OBJECT_A, 0, false /* policy_changed */);
   StorePolicy(POLICY_OBJECT_A, 0, true /* policy_changed */);
-  DisableInvalidationService();
+  EXPECT_EQ(1, GetCount(METRIC_POLICY_REFRESH_CHANGED_NO_INVALIDATIONS));
+
+  // If the clock advances less than the grace period, invalidations are OFF.
+  AdvanceClock(base::TimeDelta::FromSeconds(1));
   StorePolicy(POLICY_OBJECT_A, 0, false /* policy_changed */);
   StorePolicy(POLICY_OBJECT_A, 0, true /* policy_changed */);
+  EXPECT_EQ(2, GetCount(METRIC_POLICY_REFRESH_CHANGED_NO_INVALIDATIONS));
+
+  // After the grace period elapses, invalidations are ON.
+  AdvanceClock(base::TimeDelta::FromSeconds(
+      CloudPolicyInvalidator::kInvalidationGracePeriod));
   StorePolicy(POLICY_OBJECT_A, 0, false /* policy_changed */);
   StorePolicy(POLICY_OBJECT_A, 0, true /* policy_changed */);
   EXPECT_EQ(1, GetCount(METRIC_POLICY_REFRESH_CHANGED));
-  EXPECT_EQ(2, GetCount(METRIC_POLICY_REFRESH_CHANGED_NO_INVALIDATIONS));
-  EXPECT_EQ(3, GetCount(METRIC_POLICY_REFRESH_UNCHANGED));
-  EXPECT_EQ(0, GetCount(METRIC_POLICY_REFRESH_INVALIDATED_CHANGED));
-  EXPECT_EQ(0, GetCount(METRIC_POLICY_REFRESH_INVALIDATED_UNCHANGED));
-}
 
-TEST_F(CloudPolicyInvalidatorTest, RefreshMetricsStoreSameTimestamp) {
-  // Store loads with the same timestamp as the load which causes registration
-  // are not counted.
-  StartInvalidator();
-  StorePolicy(
-      POLICY_OBJECT_A, 0, false /* policy_changed */, 12 /* timestamp */);
-  StorePolicy(
-      POLICY_OBJECT_A, 0, false /* policy_changed */, 12 /* timestamp */);
-  StorePolicy(
-      POLICY_OBJECT_A, 0, true /* policy_changed */, 12 /* timestamp */);
+  // After the invalidation service is disabled, invalidations are OFF.
+  DisableInvalidationService();
+  StorePolicy(POLICY_OBJECT_A, 0, false /* policy_changed */);
+  StorePolicy(POLICY_OBJECT_A, 0, true /* policy_changed */);
+  EXPECT_EQ(3, GetCount(METRIC_POLICY_REFRESH_CHANGED_NO_INVALIDATIONS));
+
+  // Enabling the invalidation service results in a new grace period, so
+  // invalidations are OFF.
+  EnableInvalidationService();
+  StorePolicy(POLICY_OBJECT_A, 0, false /* policy_changed */);
+  StorePolicy(POLICY_OBJECT_A, 0, true /* policy_changed */);
+  EXPECT_EQ(4, GetCount(METRIC_POLICY_REFRESH_CHANGED_NO_INVALIDATIONS));
 
-  // The next load with a different timestamp counts.
-  StorePolicy(
-      POLICY_OBJECT_A, 0, true /* policy_changed */, 13 /* timestamp */);
+  // After the grace period elapses, invalidations are ON.
+  AdvanceClock(base::TimeDelta::FromSeconds(
+      CloudPolicyInvalidator::kInvalidationGracePeriod));
+  StorePolicy(POLICY_OBJECT_A, 0, false /* policy_changed */);
+  StorePolicy(POLICY_OBJECT_A, 0, true /* policy_changed */);
 
-  EXPECT_EQ(1, GetCount(METRIC_POLICY_REFRESH_CHANGED));
-  EXPECT_EQ(0, GetCount(METRIC_POLICY_REFRESH_CHANGED_NO_INVALIDATIONS));
-  EXPECT_EQ(0, GetCount(METRIC_POLICY_REFRESH_UNCHANGED));
+  EXPECT_EQ(2, GetCount(METRIC_POLICY_REFRESH_CHANGED));
+  EXPECT_EQ(4, GetCount(METRIC_POLICY_REFRESH_CHANGED_NO_INVALIDATIONS));
+  EXPECT_EQ(6, GetCount(METRIC_POLICY_REFRESH_UNCHANGED));
   EXPECT_EQ(0, GetCount(METRIC_POLICY_REFRESH_INVALIDATED_CHANGED));
   EXPECT_EQ(0, GetCount(METRIC_POLICY_REFRESH_INVALIDATED_UNCHANGED));
 }
@@ -817,6 +840,8 @@ TEST_F(CloudPolicyInvalidatorTest, RefreshMetricsInvalidation) {
   // the loads do not result in the invalidation being acknowledged.
   StartInvalidator();
   StorePolicy(POLICY_OBJECT_A);
+  AdvanceClock(base::TimeDelta::FromSeconds(
+      CloudPolicyInvalidator::kInvalidationGracePeriod));
   FireInvalidation(POLICY_OBJECT_A, 5, "test");
   StorePolicy(POLICY_OBJECT_A, 0, false /* policy_changed */);
   StorePolicy(POLICY_OBJECT_A, 0, true /* policy_changed */);

chrome/browser/policy/cloud/user_cloud_policy_invalidator.cc

@@ -5,7 +5,9 @@
 #include "chrome/browser/policy/cloud/user_cloud_policy_invalidator.h"
 
 #include "base/bind.h"
+#include "base/memory/scoped_ptr.h"
 #include "base/message_loop/message_loop_proxy.h"
+#include "base/time/default_clock.h"
 #include "chrome/browser/chrome_notification_types.h"
 #include "chrome/browser/invalidation/invalidation_service_factory.h"
 #include "components/policy/core/common/cloud/cloud_policy_manager.h"
@@ -18,7 +20,8 @@ UserCloudPolicyInvalidator::UserCloudPolicyInvalidator(
     CloudPolicyManager* policy_manager)
     : CloudPolicyInvalidator(
           policy_manager->core(),
-          base::MessageLoopProxy::current()),
+          base::MessageLoopProxy::current(),
+          scoped_ptr<base::Clock>(new base::DefaultClock())),
       profile_(profile) {
   DCHECK(profile);