ExtensionApiTest improvements.

This fixes a race condition where ExtensionBrowserTest::WaitForExtensionHostsToLoad() could have exited before all hosts were loaded. It simplifies the Overrides test. It also adds some debug output for aiding the hunt for remaining flakiness.

BUG=22668

Review URL: http://codereview.chromium.org/220039

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

6 files changed, 24 insertions, 19 deletions

diff --git a/chrome/browser/extensions/extension_apitest.cc b/chrome/browser/extensions/extension_apitest.cc
index 415d1c9..0a8875d 100644
--- a/chrome/browser/extensions/extension_apitest.cc
+++ b/chrome/browser/extensions/extension_apitest.cc
@@ -14,7 +14,10 @@ static const int kTimeoutMs = 60 * 1000;  // 1 minute
 
 // Load an extension and wait for it to notify of PASSED or FAILED.
 bool ExtensionApiTest::RunExtensionTest(const char* extension_name) {
+  // Note the inner scope here. The |registrar| will fall out of scope and
+  // remove listeners *before* the call to WaitForPassFail() below.
   {
+    LOG(INFO) << "Running ExtensionApiTest with: " << extension_name;
     NotificationRegistrar registrar;
     registrar.Add(this, NotificationType::EXTENSION_TEST_PASSED,
                   NotificationService::AllSources());
diff --git a/chrome/browser/extensions/extension_browsertest.cc b/chrome/browser/extensions/extension_browsertest.cc
index 0bb5542..c7e37fa 100644
--- a/chrome/browser/extensions/extension_browsertest.cc
+++ b/chrome/browser/extensions/extension_browsertest.cc
@@ -182,14 +182,14 @@ bool ExtensionBrowserTest::WaitForExtensionHostsToLoad() {
 
   ExtensionProcessManager* manager =
         browser()->profile()->GetExtensionProcessManager();
-  base::Time start_time = base::Time::Now();
-  MessageLoop::current()->PostDelayedTask(FROM_HERE,
-      new MessageLoop::QuitTask, kTimeoutMs);
   for (ExtensionProcessManager::const_iterator iter = manager->begin();
-     iter != manager->end(); ++iter) {
-    if (!(*iter)->did_stop_loading())
+       iter != manager->end();) {
+    if ((*iter)->did_stop_loading())
+      ++iter;
+    else
       ui_test_utils::RunMessageLoop();
   }
+  LOG(INFO) << "All ExtensionHosts loaded";
 
   return true;
 }
diff --git a/chrome/browser/extensions/extension_host.cc b/chrome/browser/extensions/extension_host.cc
index 489ce56..ea19514 100644
--- a/chrome/browser/extensions/extension_host.cc
+++ b/chrome/browser/extensions/extension_host.cc
@@ -94,10 +94,12 @@ bool ExtensionHost::IsRenderViewLive() const {
 }
 
 void ExtensionHost::CreateRenderView(RenderWidgetHostView* host_view) {
+  LOG(INFO) << "Creating RenderView for " + extension_->name();
   render_view_host_->set_view(host_view);
   render_view_host_->CreateRenderView();
   NavigateToURL(url_);
   DCHECK(IsRenderViewLive());
+  LOG(INFO) << "Sending EXTENSION_PROCESS_CREATED";
   NotificationService::current()->Notify(
       NotificationType::EXTENSION_PROCESS_CREATED,
       Source<Profile>(profile_),
@@ -105,6 +107,8 @@ void ExtensionHost::CreateRenderView(RenderWidgetHostView* host_view) {
 }
 
 void ExtensionHost::NavigateToURL(const GURL& url) {
+  LOG(INFO) << "Request to NavigateToURL " << url.spec() << " for "
+      << extension_->name();
   // Prevent explicit navigation to another extension id's pages.
   // This method is only called by some APIs, so we still need to protect
   // DidNavigate below (location = "").
@@ -117,11 +121,14 @@ void ExtensionHost::NavigateToURL(const GURL& url) {
   url_ = url;
 
   if (!is_background_page() && !extension_->GetBackgroundPageReady()) {
+    LOG(INFO) << "...Waiting on EXTENSION_BACKGROUND_PAGE_READY";
     // Make sure the background page loads before any others.
     registrar_.Add(this, NotificationType::EXTENSION_BACKGROUND_PAGE_READY,
                    Source<Extension>(extension_));
     return;
   }
+
+  LOG(INFO) << "Navigating to " << url_.spec();
   render_view_host_->NavigateToURL(url_);
 }
 
@@ -139,6 +146,7 @@ void ExtensionHost::UpdatePreferredWidth(int pref_width) {
 }
 
 void ExtensionHost::RenderViewGone(RenderViewHost* render_view_host) {
+  LOG(INFO) << "Sending EXTENSION_PROCESS_CRASHED for " + extension_->name();
   DCHECK_EQ(render_view_host_, render_view_host);
   NotificationService::current()->Notify(
       NotificationType::EXTENSION_PROCESS_CRASHED,
@@ -176,6 +184,8 @@ void ExtensionHost::DidNavigate(RenderViewHost* render_view_host,
     return;
   }
 
+  LOG(INFO) << "(DidNavigate) Resetting EFD to " << url_.spec() << " for "
+      << extension_->name();
   url_ = params.url;
   extension_function_dispatcher_.reset(
       new ExtensionFunctionDispatcher(render_view_host_, this, url_));
@@ -213,11 +223,12 @@ void ExtensionHost::InsertThemeCSS() {
 
 void ExtensionHost::DidStopLoading(RenderViewHost* render_view_host) {
   if (!did_stop_loading_) {
+    did_stop_loading_ = true;
+    LOG(INFO) << "Sending EXTENSION_HOST_DID_STOP_LOADING";
     NotificationService::current()->Notify(
         NotificationType::EXTENSION_HOST_DID_STOP_LOADING,
         Source<Profile>(profile_),
         Details<ExtensionHost>(this));
-    did_stop_loading_ = true;
   }
   if (extension_host_type_ == ViewType::EXTENSION_TOOLSTRIP ||
       extension_host_type_ == ViewType::EXTENSION_MOLE) {
@@ -385,6 +396,8 @@ void ExtensionHost::RenderViewCreated(RenderViewHost* render_view_host) {
   // we'll create 2 EFDs for the first navigation. We should try to find a
   // better way to unify them.
   // See http://code.google.com/p/chromium/issues/detail?id=18240
+  LOG(INFO) << "(RenderViewCreated) Resetting EFD to " << url_.spec() << " for "
+      << extension_->name();
   extension_function_dispatcher_.reset(
       new ExtensionFunctionDispatcher(render_view_host, this, url_));
 
diff --git a/chrome/browser/extensions/extension_override_apitest.cc b/chrome/browser/extensions/extension_override_apitest.cc
index 8d313f8..0ebe460 100644
--- a/chrome/browser/extensions/extension_override_apitest.cc
+++ b/chrome/browser/extensions/extension_override_apitest.cc
@@ -8,12 +8,6 @@ IN_PROC_BROWSER_TEST_F(ExtensionApiTest, Overrides) {
   // The first pass response is the creation of a new tab.
   ASSERT_TRUE(RunExtensionTest("override1")) << message_;
 
-  // The overridden new tab page also sends a pass response.
-  WaitForPassFail();
-
-  // There should be no additional pass/fail responses.
-  EXPECT_EQ(results_.size(), 0U);
-
   // TODO(erikkay) load a second override and verify behavior, then unload
   // the first and verify behavior, etc.
 }
diff --git a/chrome/browser/extensions/extensions_service.cc b/chrome/browser/extensions/extensions_service.cc
index 7b16360..dbb2f03 100644
--- a/chrome/browser/extensions/extensions_service.cc
+++ b/chrome/browser/extensions/extensions_service.cc
@@ -483,6 +483,7 @@ void ExtensionsService::OnExtensionLoaded(Extension* extension,
         if (extension->location() != Extension::LOAD)
           extension_prefs_->MigrateToPrefs(extension);
 
+        LOG(INFO) << "Sending EXTENSION_LOADED";
         NotificationService::current()->Notify(
             NotificationType::EXTENSION_LOADED,
             Source<ExtensionsService>(this),
diff --git a/chrome/test/data/extensions/api_test/override1/test.js b/chrome/test/data/extensions/api_test/override1/test.js
index 67f73a8..52db94d 100644
--- a/chrome/test/data/extensions/api_test/override1/test.js
+++ b/chrome/test/data/extensions/api_test/override1/test.js
@@ -1,7 +1 @@
-chrome.test.runTests([
-  function newtab() {
-    chrome.tabs.create({"url": "chrome://newtab/"}, 
-                       chrome.test.callbackPass(function(response) {}));
-  }
-]);
-
+chrome.tabs.create({"url": "chrome://newtab/"});