Add more debug-logging for feature engagement tracker

Up until now, there has been little help in debugging the
feature_engagement_tracker component other than seeing how the UI
behaves.

This has meant that some things are harder to evaluate and debug,
and developers typically have to add manual logging, particularly for
the check for whether in-product help should trigger.

This CL adds support for writing the ConditionValidator::Result struct
to an std::ostream using the operator<<. In addition, it makes use of
that in DVLOG(2) statements.

It also adds some extra debugging information related to startup
initialization and tracking of events.

By adding the following to the chrome command line, the extra logging
would appear in debug builds:
--vmodule=feature_engagement_tracker_impl*=2,model_impl*=2,availability_store*=2

BUG=None

Change-Id: Ifc4194d19fdec9230ad372b1d6296ffca45d5ee0
Reviewed-on: https://chromium-review.googlesource.com/526013Reviewed-by: David Trainor <dtrainor@chromium.org>
Commit-Queue: Tommy Nyquist <nyquist@chromium.org>
Cr-Commit-Position: refs/heads/master@{#478709}

components/feature_engagement_tracker/internal/availability_store.cc

@@ -81,6 +81,8 @@ void OnDBLoadComplete(
     // Both in |feature_filter| and is enabled, so keep around.
     feature_availabilities->insert(
         std::make_pair(feature->name, availability.day()));
+    DVLOG(2) << "Keeping availability for " << feature->name << " @ "
+             << availability.day();
   }
 
   // Find features from |feature_filter| that are enabled, but not in DB yet.
@@ -105,6 +107,8 @@ void OnDBLoadComplete(
     // Since it will be written to the DB, also add to the callback result.
     feature_availabilities->insert(
         std::make_pair(feature->name, availability.day()));
+    DVLOG(2) << "Adding availability for " << feature->name << " @ "
+             << availability.day();
   }
 
   // Write all changes to the DB.

components/feature_engagement_tracker/internal/condition_validator.cc

@@ -4,6 +4,8 @@
 
 #include "components/feature_engagement_tracker/internal/condition_validator.h"
 
+#include <ostream>
+
 namespace feature_engagement_tracker {
 
 ConditionValidator::Result::Result(bool initial_values)
@@ -37,4 +39,19 @@ bool ConditionValidator::Result::NoErrors() const {
          session_rate_ok && availability_model_ready_ok && availability_ok;
 }
 
+std::ostream& operator<<(std::ostream& os,
+                         const ConditionValidator::Result& result) {
+  return os << "{ event_model_ready_ok=" << result.event_model_ready_ok
+            << ", currently_showing_ok=" << result.currently_showing_ok
+            << ", feature_enabled_ok=" << result.feature_enabled_ok
+            << ", config_ok=" << result.config_ok
+            << ", used_ok=" << result.used_ok
+            << ", trigger_ok=" << result.trigger_ok
+            << ", preconditions_ok=" << result.preconditions_ok
+            << ", session_rate_ok=" << result.session_rate_ok
+            << ", availability_model_ready_ok="
+            << result.availability_model_ready_ok
+            << ", availability_ok=" << result.availability_ok << " }";
+}
+
 }  // namespace feature_engagement_tracker

components/feature_engagement_tracker/internal/condition_validator.h

@@ -7,6 +7,7 @@
 
 #include <stdint.h>
 
+#include <ostream>
 #include <string>
 
 #include "base/macros.h"
@@ -90,6 +91,9 @@ class ConditionValidator {
   DISALLOW_COPY_AND_ASSIGN(ConditionValidator);
 };
 
+std::ostream& operator<<(std::ostream& os,
+                         const ConditionValidator::Result& result);
+
 }  // namespace feature_engagement_tracker
 
 #endif  // COMPONENTS_FEATURE_ENGAGEMENT_TRACKER_INTERNAL_CONDITION_VALIDATOR_H_

components/feature_engagement_tracker/internal/feature_engagement_tracker_impl.cc

@@ -10,6 +10,7 @@
 #include "base/bind.h"
 #include "base/feature_list.h"
 #include "base/files/file_path.h"
+#include "base/logging.h"
 #include "base/memory/ptr_util.h"
 #include "base/metrics/field_trial_params.h"
 #include "base/metrics/user_metrics.h"
@@ -178,10 +179,12 @@ bool FeatureEngagementTrackerImpl::ShouldTriggerHelpUI(
   }
 
   stats::RecordShouldTriggerHelpUI(feature, result);
+  DVLOG(2) << "Trigger result for " << feature.name << ": " << result;
   return result.NoErrors();
 }
 
 void FeatureEngagementTrackerImpl::Dismissed(const base::Feature& feature) {
+  DVLOG(2) << "Dismissing " << feature.name;
   condition_validator_->NotifyDismissed(feature);
   stats::RecordUserDismiss();
 }
@@ -206,6 +209,8 @@ void FeatureEngagementTrackerImpl::OnEventModelInitializationFinished(
   DCHECK_EQ(success, model_->IsReady());
   event_model_initialization_finished_ = true;
 
+  DVLOG(2) << "Event model initialization result = " << success;
+
   MaybePostInitializedCallbacks();
 }
 
@@ -214,6 +219,8 @@ void FeatureEngagementTrackerImpl::OnAvailabilityModelInitializationFinished(
   DCHECK_EQ(success, availability_model_->IsReady());
   availability_model_initialization_finished_ = true;
 
+  DVLOG(2) << "Availability model initialization result = " << success;
+
   MaybePostInitializedCallbacks();
 }
 
@@ -226,6 +233,8 @@ void FeatureEngagementTrackerImpl::MaybePostInitializedCallbacks() {
   if (!IsInitializationFinished())
     return;
 
+  DVLOG(2) << "Initialization finished.";
+
   for (auto& callback : on_initialized_callbacks_) {
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE, base::Bind(callback, IsInitialized()));

components/feature_engagement_tracker/internal/model_impl.cc

@@ -10,6 +10,7 @@
 #include <vector>
 
 #include "base/bind.h"
+#include "base/logging.h"
 #include "base/memory/weak_ptr.h"
 #include "base/sequenced_task_runner.h"
 #include "base/single_thread_task_runner.h"
@@ -52,8 +53,12 @@ void ModelImpl::IncrementEvent(const std::string& event_name,
                                uint32_t current_day) {
   DCHECK(ready_);
 
-  if (!storage_validator_->ShouldStore(event_name))
+  if (!storage_validator_->ShouldStore(event_name)) {
+    DVLOG(2) << "Not incrementing event " << event_name << " @ " << current_day;
     return;
+  }
+
+  DVLOG(2) << "Incrementing event " << event_name << " @ " << current_day;
 
   Event& event = GetNonConstEvent(event_name);
   for (int i = 0; i < event.events_size(); ++i) {