Add verbose logging for consent setting.

This will help the telemetry team debug consent flakes in integration tests.

BUG=1041062
TEST=modified KernelWarning to use appropriate verbose flag and \
     `tast run --extrauseflags chrome_internal $DUT platform.KernelWarning`

Change-Id: I050b43b1a8578ce427ca9974c237f133115161de
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2082918Reviewed-by: Ian Barkley-Yeung <iby@chromium.org>
Reviewed-by: Achuith Bhandarkar <achuith@chromium.org>
Auto-Submit: Miriam Zimmerman <mutexlox@chromium.org>
Commit-Queue: Achuith Bhandarkar <achuith@chromium.org>
Cr-Commit-Position: refs/heads/master@{#747171}

chrome/browser/chromeos/extensions/autotest_private/autotest_private_api.cc

@@ -3915,7 +3915,8 @@ AutotestPrivateSetMetricsEnabledFunction::Run() {
   std::unique_ptr<api::autotest_private::SetMetricsEnabled::Params> params(
       api::autotest_private::SetMetricsEnabled::Params::Create(*args_));
   EXTENSION_FUNCTION_VALIDATE(params);
-  DVLOG(1) << "AutotestPrivateSetMetricsEnabledFunction " << params->enabled;
+  VLOG(1) << "AutotestPrivateSetMetricsEnabledFunction " << std::boolalpha
+          << params->enabled;
 
   target_value_ = params->enabled;
 
@@ -3927,6 +3928,7 @@ AutotestPrivateSetMetricsEnabledFunction::Run() {
   // Set the preference to indicate metrics are enabled/disabled.
   stats_reporting_controller->SetEnabled(profile, target_value_);
   if (stats_reporting_controller->IsEnabled() == target_value_) {
+    VLOG(1) << "Value at target; returning early";
     return RespondNow(NoArguments());
   }
   stats_reporting_observer_subscription_ =
@@ -3938,7 +3940,11 @@ AutotestPrivateSetMetricsEnabledFunction::Run() {
 }
 
 void AutotestPrivateSetMetricsEnabledFunction::OnStatsReportingStateChanged() {
-  if (chromeos::StatsReportingController::Get()->IsEnabled() == target_value_) {
+  bool actual = chromeos::StatsReportingController::Get()->IsEnabled();
+  VLOG(1) << "AutotestPrivateSetMetricsEnabledFunction: actual: "
+          << std::boolalpha << actual << " and expected: " << std::boolalpha
+          << target_value_;
+  if (actual == target_value_) {
     Respond(NoArguments());
   } else {
     Respond(Error("Failed to set metrics consent"));

chrome/browser/chromeos/settings/stats_reporting_controller.cc

@@ -62,10 +62,12 @@ void StatsReportingController::RegisterLocalStatePrefs(
 void StatsReportingController::SetEnabled(Profile* profile, bool enabled) {
   DCHECK(profile);
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
+  VLOG(1) << "SetEnabled(" << std::boolalpha << enabled << ")";
 
   if (GetOwnershipStatus() == DeviceSettingsService::OWNERSHIP_TAKEN) {
     // The device has an owner. If the current profile is that owner, we will
     // write the value on their behalf, otherwise no action is taken.
+    VLOG(1) << "Already has owner";
     SetWithServiceAsync(GetOwnerSettingsService(profile), enabled);
   } else {
     // The device has no owner, or we do not know yet whether the device has an
@@ -74,6 +76,7 @@ void StatsReportingController::SetEnabled(Profile* profile, bool enabled) {
     // We store the new value in the local state, so that even if Chrome is
     // restarted before ownership is taken, we will still persist it eventually.
     // See OnOwnershipTaken.
+    VLOG(1) << "Pending owner; setting kPendingPref";
     local_state_->SetBoolean(kPendingPref, enabled);
     NotifyObservers();
   }
@@ -103,6 +106,7 @@ void StatsReportingController::OnOwnershipTaken(
     ownership::OwnerSettingsService* service) {
   DCHECK_EQ(GetOwnershipStatus(), DeviceSettingsService::OWNERSHIP_TAKEN);
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
+  VLOG(1) << "OnOwnershipTaken";
 
   bool pending_value;
   if (GetPendingValue(&pending_value)) {
@@ -128,8 +132,10 @@ StatsReportingController::~StatsReportingController() {
 void StatsReportingController::SetWithServiceAsync(
     ownership::OwnerSettingsService* service,  // Can be null for non-owners.
     bool enabled) {
+  VLOG(1) << "SetWithServiceAsync(" << std::boolalpha << enabled << ")";
   bool not_yet_ready = service && !service->IsReady();
   if (not_yet_ready) {
+    VLOG(1) << "Service not yet ready. Adding listener.";
     // Service is not yet ready. Listen for changes in its readiness so we can
     // write the value once it is ready. Uses weak pointers, so if everything
     // is shutdown and deleted in the meantime, this callback isn't run.
@@ -146,6 +152,7 @@ void StatsReportingController::SetWithServiceCallback(
     const base::WeakPtr<ownership::OwnerSettingsService>& service,
     bool enabled,
     bool is_owner) {
+  VLOG(1) << "SetWithServiceCallback(" << std::boolalpha << enabled << ")";
   if (service)  // Make sure service wasn't deleted in the meantime.
     SetWithService(service.get(), enabled);
 }
@@ -153,6 +160,7 @@ void StatsReportingController::SetWithServiceCallback(
 void StatsReportingController::SetWithService(
     ownership::OwnerSettingsService* service,  // Can be null for non-owners.
     bool enabled) {
+  VLOG(1) << "SetWithService(" << std::boolalpha << enabled << ")";
   if (service && service->IsOwner()) {
     service->SetBoolean(kStatsReportingPref, enabled);
     ClearPendingValue();
@@ -167,9 +175,13 @@ void StatsReportingController::SetWithService(
 void StatsReportingController::NotifyObservers() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
   bool current_value = IsEnabled();
+  VLOG(1) << "Maybe notifying observers of " << std::boolalpha << current_value;
   if (current_value != value_notified_to_observers_) {
+    VLOG(1) << "Notifying observers";
     value_notified_to_observers_ = current_value;
     callback_list_.Notify();
+  } else {
+    VLOG(1) << "Not notifying (already notified)";
   }
 }
 
@@ -192,6 +204,7 @@ bool StatsReportingController::GetPendingValue(bool* result) {
 }
 
 void StatsReportingController::ClearPendingValue() {
+  VLOG(1) << "ClearPendingValue";
   local_state_->ClearPref(kPendingPref);
 }