Change default mode of extension install verification

Right now the default mode is to make requests against the server unless
the experiment group says not to, and that may be contributing to some
unexpected load we're seeing. So this CL changes it to not do that.

It also adds some histograms to help measure the success rate and
sources of requests to the server.

[This is a resubmit of https://codereview.chromium.org/149353002 with a
compile error fixed]

BUG=335379
TBR=finnur@chromium.org

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

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

chrome/browser/extensions/extension_service.cc

@@ -188,6 +188,36 @@ class SharedModuleProvider : public extensions::ManagementPolicy::Provider {
   DISALLOW_COPY_AND_ASSIGN(SharedModuleProvider);
 };
 
+enum VerifyAllSuccess {
+  VERIFY_ALL_BOOTSTRAP_SUCCESS = 0,
+  VERIFY_ALL_BOOTSTRAP_FAILURE,
+  VERIFY_ALL_NON_BOOTSTRAP_SUCCESS,
+  VERIFY_ALL_NON_BOOTSTRAP_FAILURE,
+
+  // Used in histograms. Do not remove/reorder any entries above, and the below
+  // MAX entry should always come last.
+
+  VERIFY_ALL_SUCCESS_MAX
+};
+
+void LogVerifyAllSuccessHistogram(bool bootstrap, bool success) {
+  VerifyAllSuccess result;
+  if (bootstrap && success)
+    result = VERIFY_ALL_BOOTSTRAP_SUCCESS;
+  else if (bootstrap && !success)
+    result = VERIFY_ALL_BOOTSTRAP_FAILURE;
+  else if (!bootstrap && success)
+    result = VERIFY_ALL_NON_BOOTSTRAP_SUCCESS;
+  else
+    result = VERIFY_ALL_NON_BOOTSTRAP_FAILURE;
+
+  UMA_HISTOGRAM_ENUMERATION("ExtensionService.VerifyAllSuccess",
+                            result, VERIFY_ALL_SUCCESS_MAX);
+}
+
+void LogAddVerifiedSuccess(bool success) {
+  UMA_HISTOGRAM_BOOLEAN("ExtensionService.AddVerified", success);
+}
 
 }  // namespace
 
@@ -551,7 +581,7 @@ void ExtensionService::Init() {
     InstallVerifier* verifier =
         extensions::ExtensionSystem::Get(profile_)->install_verifier();
     if (verifier->NeedsBootstrap())
-      VerifyAllExtensions();
+      VerifyAllExtensions(true);  // bootstrap=true.
     base::MessageLoop::current()->PostDelayedTask(
         FROM_HERE,
         base::Bind(&ExtensionService::GarbageCollectExtensions, AsWeakPtr()),
@@ -585,7 +615,7 @@ void ExtensionService::LoadGreylistFromPrefs() {
   }
 }
 
-void ExtensionService::VerifyAllExtensions() {
+void ExtensionService::VerifyAllExtensions(bool bootstrap) {
   ExtensionIdSet to_add;
   scoped_ptr<ExtensionSet> all_extensions = GenerateInstalledExtensionsSet();
 
@@ -598,10 +628,11 @@ void ExtensionService::VerifyAllExtensions() {
   }
   extensions::ExtensionSystem::Get(profile_)->install_verifier()->AddMany(
       to_add, base::Bind(&ExtensionService::FinishVerifyAllExtensions,
-                         AsWeakPtr()));
+                         AsWeakPtr(), bootstrap));
 }
 
-void ExtensionService::FinishVerifyAllExtensions(bool success) {
+void ExtensionService::FinishVerifyAllExtensions(bool bootstrap, bool success) {
+  LogVerifyAllSuccessHistogram(bootstrap, success);
   if (success) {
     // Check to see if any currently unverified extensions became verified.
     InstallVerifier* verifier =
@@ -2216,7 +2247,7 @@ void ExtensionService::AddNewOrUpdatedExtension(
   delayed_installs_.Remove(extension->id());
   if (InstallVerifier::NeedsVerification(*extension)) {
     extensions::ExtensionSystem::Get(profile_)->install_verifier()->Add(
-        extension->id(), InstallVerifier::AddResultCallback());
+        extension->id(), base::Bind(LogAddVerifiedSuccess));
   }
   FinishInstallation(extension);
 }

chrome/browser/extensions/extension_service.h

@@ -199,12 +199,15 @@ class ExtensionService
   // Initialize and start all installed extensions.
   void Init();
 
-  // Attempts to verify all extensions using the InstallVerifier.
-  void VerifyAllExtensions();
+  // Attempts to verify all extensions using the InstallVerifier. The
+  // |bootstrap| parameter indicates whether we're doing this because the
+  // InstallVerifier needed to be bootstrapped (otherwise it's for another
+  // reason, e.g. extension install/uninstall).
+  void VerifyAllExtensions(bool bootstrap);
 
   // Once the verifier work is finished, we may want to re-check management
   // policy if |success| indicates the verifier got a new signature back.
-  void FinishVerifyAllExtensions(bool success);
+  void FinishVerifyAllExtensions(bool bootstrap, bool success);
 
   // Called when the associated Profile is going to be destroyed.
   void Shutdown();

chrome/browser/extensions/install_signer.cc

@@ -9,13 +9,16 @@
 #include "base/command_line.h"
 #include "base/json/json_reader.h"
 #include "base/json/json_writer.h"
+#include "base/lazy_instance.h"
 #include "base/message_loop/message_loop.h"
 #include "base/metrics/histogram.h"
+#include "base/process/process_info.h"
 #include "base/stl_util.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_split.h"
 #include "base/strings/string_util.h"
 #include "base/strings/stringprintf.h"
+#include "base/time/time.h"
 #include "base/values.h"
 #include "chrome/common/chrome_switches.h"
 #include "chrome/common/extensions/extension_constants.h"
@@ -243,6 +246,44 @@ ExtensionIdSet InstallSigner::GetForcedNotFromWebstore() {
   return ExtensionIdSet(ids.begin(), ids.end());
 }
 
+namespace {
+
+static int g_request_count = 0;
+
+base::LazyInstance<base::TimeTicks> g_last_request_time =
+    LAZY_INSTANCE_INITIALIZER;
+
+base::LazyInstance<base::ThreadChecker> g_single_thread_checker =
+    LAZY_INSTANCE_INITIALIZER;
+
+void LogRequestStartHistograms() {
+  // Make sure we only ever call this from one thread, so that we don't have to
+  // worry about race conditions setting g_last_request_time.
+  DCHECK(g_single_thread_checker.Get().CalledOnValidThread());
+
+  // CurrentProcessInfo::CreationTime is only defined on some platforms.
+#if defined(OS_MACOSX) || defined(OS_WIN) || defined(OS_LINUX)
+  const base::Time process_creation_time =
+      base::CurrentProcessInfo::CreationTime();
+  UMA_HISTOGRAM_COUNTS("ExtensionInstallSigner.UptimeAtTimeOfRequest",
+                       (base::Time::Now() - process_creation_time).InSeconds());
+#endif  // defined(OS_MACOSX) || defined(OS_WIN) || defined(OS_LINUX)
+
+  base::TimeDelta delta;
+  base::TimeTicks now = base::TimeTicks::Now();
+  if (!g_last_request_time.Get().is_null())
+    delta = now - g_last_request_time.Get();
+  g_last_request_time.Get() = now;
+  UMA_HISTOGRAM_COUNTS("ExtensionInstallSigner.SecondsSinceLastRequest",
+                       delta.InSeconds());
+
+  g_request_count += 1;
+  UMA_HISTOGRAM_COUNTS_100("ExtensionInstallSigner.RequestCount",
+                           g_request_count);
+}
+
+}  // namespace
+
 void InstallSigner::GetSignature(const SignatureCallback& callback) {
   CHECK(!url_fetcher_.get());
   CHECK(callback_.is_null());
@@ -301,6 +342,7 @@ void InstallSigner::GetSignature(const SignatureCallback& callback) {
     return;
   }
   url_fetcher_->SetUploadData("application/json", json);
+  LogRequestStartHistograms();
   url_fetcher_->Start();
 }
 
@@ -311,10 +353,17 @@ void InstallSigner::ReportErrorViaCallback() {
 }
 
 void InstallSigner::ParseFetchResponse() {
+  bool fetch_success = url_fetcher_->GetStatus().is_success();
+  UMA_HISTOGRAM_BOOLEAN("ExtensionInstallSigner.FetchSuccess", fetch_success);
+
   std::string response;
-  if (!url_fetcher_->GetStatus().is_success() ||
-      !url_fetcher_->GetResponseAsString(&response) ||
-      response.empty()) {
+  if (fetch_success) {
+    if (!url_fetcher_->GetResponseAsString(&response))
+      response.clear();
+  }
+  UMA_HISTOGRAM_BOOLEAN("ExtensionInstallSigner.GetResponseSuccess",
+                        !response.empty());
+  if (!fetch_success || response.empty()) {
     ReportErrorViaCallback();
     return;
   }
@@ -331,7 +380,10 @@ void InstallSigner::ParseFetchResponse() {
 
   base::DictionaryValue* dictionary = NULL;
   scoped_ptr<base::Value> parsed(base::JSONReader::Read(response));
-  if (!parsed.get() || !parsed->GetAsDictionary(&dictionary)) {
+  bool json_success = parsed.get() && parsed->GetAsDictionary(&dictionary);
+  UMA_HISTOGRAM_BOOLEAN("ExtensionInstallSigner.ParseJsonSuccess",
+                        json_success);
+  if (!json_success) {
     ReportErrorViaCallback();
     return;
   }
@@ -345,9 +397,13 @@ void InstallSigner::ParseFetchResponse() {
   dictionary->GetString(kSignatureKey, &signature_base64);
   dictionary->GetString(kExpiryKey, &expire_date);
 
-  if (protocol_version != 1 || signature_base64.empty() ||
-      !ValidateExpireDateFormat(expire_date) ||
-      !base::Base64Decode(signature_base64, &signature)) {
+  bool fields_success =
+      protocol_version == 1 && !signature_base64.empty() &&
+      ValidateExpireDateFormat(expire_date) &&
+      base::Base64Decode(signature_base64, &signature);
+  UMA_HISTOGRAM_BOOLEAN("ExtensionInstallSigner.ParseFieldsSuccess",
+                        fields_success);
+  if (!fields_success) {
     ReportErrorViaCallback();
     return;
   }

chrome/browser/extensions/install_verifier.cc

@@ -30,6 +30,11 @@ enum VerifyStatus {
   NONE = 0,   // Do not request install signatures, and do not enforce them.
   BOOTSTRAP,  // Request install signatures, but do not enforce them.
   ENFORCE,    // Request install signatures, and enforce them.
+
+  // This is used in histograms - do not remove or reorder entries above! Also
+  // the "MAX" item below should always be the last element.
+
+  VERIFY_STATUS_MAX
 };
 
 #if defined(GOOGLE_CHROME_BUILD)
@@ -49,7 +54,7 @@ VerifyStatus GetExperimentStatus() {
     return ENFORCE;
   }
 
-  VerifyStatus default_status = BOOTSTRAP;
+  VerifyStatus default_status = NONE;
 
   if (group == "Enforce")
     return ENFORCE;
@@ -141,6 +146,11 @@ bool InstallVerifier::NeedsVerification(const Extension& extension) {
 }
 
 void InstallVerifier::Init() {
+  UMA_HISTOGRAM_ENUMERATION("ExtensionInstallVerifier.ExperimentStatus",
+                            GetExperimentStatus(), VERIFY_STATUS_MAX);
+  UMA_HISTOGRAM_ENUMERATION("ExtensionInstallVerifier.ActualStatus",
+                            GetStatus(), VERIFY_STATUS_MAX);
+
   const base::DictionaryValue* pref = prefs_->GetInstallSignature();
   if (pref) {
     scoped_ptr<InstallSignature> signature_from_prefs =

chrome/browser/ui/webui/extensions/extension_settings_handler.cc

@@ -16,6 +16,7 @@
 #include "base/command_line.h"
 #include "base/location.h"
 #include "base/message_loop/message_loop.h"
+#include "base/metrics/histogram.h"
 #include "base/prefs/pref_service.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_util.h"
@@ -758,9 +759,11 @@ void ExtensionSettingsHandler::HandleRequestExtensionsData(
       "extensions.ExtensionSettings.returnExtensionsData", results);
 
   MaybeRegisterForNotifications();
+  UMA_HISTOGRAM_BOOLEAN("ExtensionSettings.ShouldDoVerificationCheck",
+                        should_do_verification_check_);
   if (should_do_verification_check_) {
     should_do_verification_check_ = false;
-    extension_service_->VerifyAllExtensions();
+    extension_service_->VerifyAllExtensions(false);  // bootstrap=false.
   }
 }