Add queue for UserEventSyncBridge

Implement an in-memory queue for UserEventSyncBridge to keep user consent
events while the store or change processor are not ready yet. The queue
will be processed as soon as store and change processor are initialized.

Bug: 781765

Change-Id: I0a7fb25d66dce548c0f1ae9cf5f99e869ea54ddc
Reviewed-on: https://chromium-review.googlesource.com/980975Reviewed-by: Gayane Petrosyan <gayane@chromium.org>
Reviewed-by: Mihai Sardarescu <msarda@chromium.org>
Reviewed-by: Martin Šrámek <msramek@chromium.org>
Reviewed-by: Mikel Astiz <mastiz@chromium.org>
Commit-Queue: Christian Dullweber <dullweber@chromium.org>
Cr-Commit-Position: refs/heads/master@{#548132}

chrome/browser/signin/dice_browsertest.cc

@@ -440,19 +440,6 @@ class DiceBrowserTestBase : public InProcessBrowserTest,
     // stable state.
     reconcilor->AbortReconcile();
     reconcilor->AddObserver(this);
-
-    // TODO(crbug.com/709094, crbug.com/761485): This browsertest exercises
-    // the Sync confirmation dialog and thus triggers consent recording. For
-    // that to happen successfully, UserEventSyncBridge must be ready to
-    // receive events. UserEventSyncBridge initializes asynchronously which
-    // is not a problem for regular usage, but in this browsertest, we must
-    // give it enough time to do so.
-    while (!browser_sync::UserEventServiceFactory::GetForProfile(
-                browser()->profile())
-                ->GetSyncBridge()
-                ->change_processor()
-                ->IsTrackingMetadata())
-      base::RunLoop().RunUntilIdle();
   }
 
   void TearDownOnMainThread() override {

chrome/browser/sync/test/integration/single_client_user_events_sync_test.cc

@@ -270,20 +270,17 @@ IN_PROC_BROWSER_TEST_F(SingleClientUserEventsSyncTest, NoHistory) {
   EXPECT_TRUE(ExpectUserEvents({testEvent1, consent1, consent2, testEvent3}));
 }
 
-// Test that events that are logged before sync is enabled.
+// Test that events that are logged before sync is enabled don't get lost.
 IN_PROC_BROWSER_TEST_F(SingleClientUserEventsSyncTest, LoggedBeforeSyncSetup) {
   const UserEventSpecifics consent1 = CreateUserConsent(1);
   const UserEventSpecifics consent2 = CreateUserConsent(2);
   ASSERT_TRUE(SetupClients());
   syncer::UserEventService* event_service =
       browser_sync::UserEventServiceFactory::GetForProfile(GetProfile(0));
-  auto bridge = event_service->GetSyncBridge();
-  // Wait for UserEventSyncBridge to be ready to receive events.
-  // TODO(crbug.com/761485): Remove when the store is initialized instantly.
-  while (!bridge->change_processor()->IsTrackingMetadata())
-    base::RunLoop().RunUntilIdle();
   event_service->RecordUserEvent(consent1);
+  EXPECT_TRUE(ExpectUserEvents({}));
   ASSERT_TRUE(SetupSync());
+  EXPECT_TRUE(ExpectUserEvents({consent1}));
   event_service->RecordUserEvent(consent2);
   EXPECT_TRUE(ExpectUserEvents({consent1, consent2}));
 }

components/consent_auditor/consent_auditor.cc

@@ -105,26 +105,6 @@ void ConsentAuditor::RecordGaiaConsent(
 
   std::unique_ptr<sync_pb::UserEventSpecifics> specifics = ConstructUserConsent(
       feature, description_grd_ids, confirmation_grd_id, status);
-  // UserEventSyncBridge initializes asynchronously. Currently, instantiating
-  // UserEventService early in the Profile lifetime bootstraps
-  // the initialization so that it should be ready in practice, but this is
-  // not certain. Exit if it is not the case. Record a histogram to measure
-  // how often that happens.
-  // TODO(crbug.com/709094, crbug.com/761485): Remove this check and histogram
-  // when the store initializes synchronously and is instantly ready to receive
-  // data.
-  bool event_service_ready = !user_event_service_->GetSyncBridge() ||
-                             user_event_service_->GetSyncBridge()
-                                 ->change_processor()
-                                 ->IsTrackingMetadata();
-  UMA_HISTOGRAM_BOOLEAN("Privacy.ConsentAuditor.UserEventServiceReady",
-                        event_service_ready);
-  if (!event_service_ready) {
-    VLOG(1) << "Consent recording failed. The UserEventService has not been "
-               "initialized.";
-    return;
-  }
-
   user_event_service_->RecordUserEvent(std::move(specifics));
 }
 

components/sync/user_events/user_event_sync_bridge.cc

@@ -81,7 +81,10 @@ UserEventSyncBridge::UserEventSyncBridge(
       &UserEventSyncBridge::HandleGlobalIdChange, base::AsWeakPtr(this)));
 }
 
-UserEventSyncBridge::~UserEventSyncBridge() {}
+UserEventSyncBridge::~UserEventSyncBridge() {
+  if (!deferred_user_events_while_initializing_.empty())
+    LOG(ERROR) << "Non-empty event queue at shutdown!";
+}
 
 std::unique_ptr<MetadataChangeList>
 UserEventSyncBridge::CreateMetadataChangeList() {
@@ -147,27 +150,28 @@ std::string UserEventSyncBridge::GetStorageKey(const EntityData& entity_data) {
 
 void UserEventSyncBridge::ApplyDisableSyncChanges(
     std::unique_ptr<MetadataChangeList> delete_metadata_change_list) {
+  // Sync can only be disabled after initialization.
+  DCHECK(deferred_user_events_while_initializing_.empty());
   // No data should be retained through sign out.
   store_->DeleteAllDataAndMetadata(base::DoNothing());
 }
 
 void UserEventSyncBridge::RecordUserEvent(
     std::unique_ptr<UserEventSpecifics> specifics) {
-  // TODO(skym): Remove this when ModelTypeStore synchronously returns a
-  // partially initialized reference, see crbug.com/709094.
-  if (!store_) {
-    return;
-  }
-  // TODO(skym): Remove this when the processor can handle Put() calls before
-  // being given metadata, see crbug.com/761485. Dropping data on the floor here
-  // is better than just writing to the store, because it will be lost if sent
-  // to just the store, and bloat persistent storage indefinitely.
-  if (!change_processor()->IsTrackingMetadata()) {
+  if (change_processor()->IsTrackingMetadata()) {
+    RecordUserEventImpl(std::move(specifics));
     return;
   }
+  if (specifics->has_user_consent())
+    deferred_user_events_while_initializing_.push_back(std::move(specifics));
+}
 
-  std::string storage_key = GetStorageKeyFromSpecifics(*specifics);
+void UserEventSyncBridge::RecordUserEventImpl(
+    std::unique_ptr<UserEventSpecifics> specifics) {
+  DCHECK(store_);
+  DCHECK(change_processor()->IsTrackingMetadata());
 
+  std::string storage_key = GetStorageKeyFromSpecifics(*specifics);
   // There are two scenarios we need to guard against here. First, the given
   // user even may have been read from an old global_id timestamp off of a
   // navigation, which has already been re-written. In this case, we should be
@@ -195,6 +199,15 @@ void UserEventSyncBridge::RecordUserEvent(
       base::Bind(&UserEventSyncBridge::OnCommit, base::AsWeakPtr(this)));
 }
 
+void UserEventSyncBridge::ProcessQueuedEvents() {
+  DCHECK(change_processor()->IsTrackingMetadata());
+  for (std::unique_ptr<sync_pb::UserEventSpecifics>& event :
+       deferred_user_events_while_initializing_) {
+    RecordUserEventImpl(std::move(event));
+  }
+  deferred_user_events_while_initializing_.clear();
+}
+
 void UserEventSyncBridge::OnStoreCreated(
     const base::Optional<ModelError>& error,
     std::unique_ptr<ModelTypeStore> store) {
@@ -215,6 +228,8 @@ void UserEventSyncBridge::OnReadAllMetadata(
     change_processor()->ReportError(*error);
   } else {
     change_processor()->ModelReadyToSync(this, std::move(metadata_batch));
+    DCHECK(change_processor()->IsTrackingMetadata());
+    ProcessQueuedEvents();
   }
 }
 

components/sync/user_events/user_event_sync_bridge.h

@@ -10,6 +10,7 @@
 #include <map>
 #include <memory>
 #include <string>
+#include <vector>
 
 #include "base/macros.h"
 #include "base/optional.h"
@@ -46,6 +47,10 @@ class UserEventSyncBridge : public ModelTypeSyncBridge {
   void RecordUserEvent(std::unique_ptr<sync_pb::UserEventSpecifics> specifics);
 
  private:
+  void RecordUserEventImpl(
+      std::unique_ptr<sync_pb::UserEventSpecifics> specifics);
+  void ProcessQueuedEvents();
+
   void OnStoreCreated(const base::Optional<ModelError>& error,
                       std::unique_ptr<ModelTypeStore> store);
   void OnReadAllMetadata(const base::Optional<ModelError>& error,
@@ -65,6 +70,11 @@ class UserEventSyncBridge : public ModelTypeSyncBridge {
   // delete upon commit confirmation.
   std::unique_ptr<ModelTypeStore> store_;
 
+  // Used to store important events while the store or change processor are not
+  // ready. This currently only handles user consents.
+  std::vector<std::unique_ptr<sync_pb::UserEventSpecifics>>
+      deferred_user_events_while_initializing_;
+
   // The key is the global_id of the navigation the event is linked to.
   std::multimap<int64_t, sync_pb::UserEventSpecifics>
       in_flight_nav_linked_events_;

components/sync/user_events/user_event_sync_bridge_unittest.cc

@@ -11,6 +11,7 @@
 #include "base/bind.h"
 #include "base/message_loop/message_loop.h"
 #include "base/run_loop.h"
+#include "base/test/bind_test_util.h"
 #include "components/sync/driver/fake_sync_service.h"
 #include "components/sync/model/data_batch.h"
 #include "components/sync/model/mock_model_type_change_processor.h"
@@ -321,6 +322,59 @@ TEST_F(UserEventSyncBridgeTest, RecordBeforeMetadataLoads) {
   EXPECT_THAT(GetAllData(), IsEmpty());
 }
 
+// User consents should be buffered if the bridge is not fully initialized.
+// Other events should get dropped.
+TEST_F(UserEventSyncBridgeTest, RecordWithLateInitializedStore) {
+  // Wait until bridge() is ready to avoid interference with processor() mock.
+  base::RunLoop().RunUntilIdle();
+
+  UserEventSpecifics consent1 = CreateSpecifics(1u, 1u, 1u);
+  consent1.mutable_user_consent();
+  UserEventSpecifics consent2 = CreateSpecifics(2u, 2u, 2u);
+  consent2.mutable_user_consent();
+  UserEventSpecifics specifics1 = CreateSpecifics(3u, 3u, 3u);
+  UserEventSpecifics specifics2 = CreateSpecifics(4u, 4u, 4u);
+
+  ON_CALL(*processor(), IsTrackingMetadata()).WillByDefault(Return(false));
+  ModelType store_init_type;
+  ModelTypeStore::InitCallback store_init_callback;
+  UserEventSyncBridge late_init_bridge(
+      base::BindLambdaForTesting(
+          [&](ModelType type, ModelTypeStore::InitCallback callback) {
+            store_init_type = type;
+            store_init_callback = std::move(callback);
+          }),
+      processor()->CreateForwardingProcessor(), mapper());
+
+  // Record events before the store is created. Only the consent will be
+  // buffered, the other event is dropped.
+  late_init_bridge.RecordUserEvent(
+      std::make_unique<UserEventSpecifics>(consent1));
+  late_init_bridge.RecordUserEvent(
+      std::make_unique<UserEventSpecifics>(specifics1));
+
+  // Initialize the store.
+  EXPECT_CALL(*processor(), DoModelReadyToSync(&late_init_bridge, NotNull()));
+  ON_CALL(*processor(), IsTrackingMetadata()).WillByDefault(Return(true));
+  std::move(store_init_callback)
+      .Run(base::nullopt,
+           ModelTypeStoreTestUtil::CreateInMemoryStoreForTest(store_init_type));
+
+  // Record events after metadata is ready.
+  late_init_bridge.RecordUserEvent(
+      std::make_unique<UserEventSpecifics>(consent2));
+  late_init_bridge.RecordUserEvent(
+      std::make_unique<UserEventSpecifics>(specifics2));
+
+  base::RunLoop().RunUntilIdle();
+  ASSERT_THAT(
+      GetAllData(),
+      UnorderedElementsAre(
+          Pair(GetStorageKey(consent1), MatchesUserEvent(consent1)),
+          Pair(GetStorageKey(consent2), MatchesUserEvent(consent2)),
+          Pair(GetStorageKey(specifics2), MatchesUserEvent(specifics2))));
+}
+
 }  // namespace
 
 }  // namespace syncer

tools/metrics/histograms/histograms.xml

@@ -71071,6 +71071,9 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
 </histogram>
 
 <histogram name="Privacy.ConsentAuditor.UserEventServiceReady" enum="Boolean">
+  <obsolete>
+    Deprecated as of 4/2018.
+  </obsolete>
   <owner>dullweber@google.com</owner>
   <owner>msramek@google.com</owner>
   <summary>