Add logs to understand failures that only happen on the waterfall. Will revert once browser tests start.

TEST=ExtensionHistoryApiTest.*
TBR=skerner

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

4 files changed, 43 insertions, 22 deletions

diff --git a/chrome/browser/extensions/extension_history_api.cc b/chrome/browser/extensions/extension_history_api.cc
index 49929bd..2016a77 100644
--- a/chrome/browser/extensions/extension_history_api.cc
+++ b/chrome/browser/extensions/extension_history_api.cc
@@ -120,6 +120,12 @@ void ExtensionHistoryEventRouter::HistoryUrlVisited(
 
   std::string json_args;
   base::JSONWriter::Write(&args, false, &json_args);
+
+  // Logging to discover if this happens after search on XP in
+  // ExtensionHistoryTest.*.
+  LOG(WARNING) << "ExtensionHistoryEventRouter::HistoryUrlVisited(): "
+               << json_args;
+
   DispatchEvent(profile, keys::kOnVisited, json_args);
 }
 
@@ -140,6 +146,12 @@ void ExtensionHistoryEventRouter::HistoryUrlsRemoved(
 
   std::string json_args;
   base::JSONWriter::Write(&args, false, &json_args);
+
+  // Logging to discover if this happens after search on XP in
+  // ExtensionHistoryTest.*.
+  LOG(WARNING) << "ExtensionHistoryEventRouter::HistoryUrlRemoved(): "
+               << json_args;
+
   DispatchEvent(profile, keys::kOnVisitRemoved, json_args);
 }
 
diff --git a/chrome/browser/extensions/extension_history_apitest.cc b/chrome/browser/extensions/extension_history_apitest.cc
index a0b3fbe..b27c883 100644
--- a/chrome/browser/extensions/extension_history_apitest.cc
+++ b/chrome/browser/extensions/extension_history_apitest.cc
@@ -31,21 +31,21 @@ class ExtensionHistoryApiTest : public ExtensionApiTest {
 };
 
 // Flaky, http://crbug.com/26296.
-IN_PROC_BROWSER_TEST_F(ExtensionHistoryApiTest, FLAKY_MiscSearch) {
+IN_PROC_BROWSER_TEST_F(ExtensionHistoryApiTest, MiscSearch) {
   ASSERT_TRUE(RunExtensionSubtest("history", "misc_search.html")) << message_;
 }
 
 // Flaky, http://crbug.com/26296.
-IN_PROC_BROWSER_TEST_F(ExtensionHistoryApiTest, FLAKY_TimedSearch) {
+IN_PROC_BROWSER_TEST_F(ExtensionHistoryApiTest, TimedSearch) {
   ASSERT_TRUE(RunExtensionSubtest("history", "timed_search.html")) << message_;
 }
 
 // Flaky, http://crbug.com/26296.
-IN_PROC_BROWSER_TEST_F(ExtensionHistoryApiTest, FLAKY_Delete) {
+IN_PROC_BROWSER_TEST_F(ExtensionHistoryApiTest, Delete) {
   ASSERT_TRUE(RunExtensionSubtest("history", "delete.html")) << message_;
 }
 
 // Flaky, http://crbug.com/26296.
-IN_PROC_BROWSER_TEST_F(ExtensionHistoryApiTest, FLAKY_GetVisits) {
+IN_PROC_BROWSER_TEST_F(ExtensionHistoryApiTest, GetVisits) {
   ASSERT_TRUE(RunExtensionSubtest("history", "get_visits.html")) << message_;
 }
diff --git a/chrome/browser/history/history_backend.cc b/chrome/browser/history/history_backend.cc
index b303dc12..d8987f9 100644
--- a/chrome/browser/history/history_backend.cc
+++ b/chrome/browser/history/history_backend.cc
@@ -504,6 +504,7 @@ void HistoryBackend::AddPage(scoped_refptr<HistoryAddPageArgs> request) {
   }
 
   if (text_database_.get()) {
+    LOG(WARNING) << "text_database_->AddPageURL( "<< request->url.possibly_invalid_spec() << " );";
     text_database_->AddPageURL(request->url, last_ids.first, last_ids.second,
                                last_recorded_time_);
   }
@@ -1208,15 +1209,15 @@ void HistoryBackend::QueryHistoryBasic(URLDatabase* url_db,
 
     // Add a result row for this visit, get the URL info from the DB.
     if (!url_db->GetURLRow(visit.url_id, &url_result)) {
-      VLOG(0) << "Failed to get id " << visit.url_id
-              << " from history.urls.";
+      LOG(WARNING) << "Failed to get id " << visit.url_id
+                   << " from history.urls.";
       continue;  // DB out of sync and URL doesn't exist, try to recover.
     }
 
     if (!url_result.url().is_valid()) {
-      VLOG(0) << "Got invalid URL from history.urls with id "
-              << visit.url_id << ":  "
-              << url_result.url().possibly_invalid_spec();
+      LOG(WARNING) << "Got invalid URL from history.urls with id "
+                   << visit.url_id << ":  "
+                   << url_result.url().possibly_invalid_spec();
       continue;  // Don't report invalid URLs in case of corruption.
     }
 
diff --git a/chrome/test/data/extensions/api_test/history/common.js b/chrome/test/data/extensions/api_test/history/common.js
index e3eeb8e..b9ce233 100644
--- a/chrome/test/data/extensions/api_test/history/common.js
+++ b/chrome/test/data/extensions/api_test/history/common.js
@@ -155,19 +155,27 @@ function addUrlsWithTimeline(urls, callback) {
     // to pass to the callback.
     chrome.history.search({text: ''}, function(historyItems) {
       // Check that both URLs were added.
-      assertEq(urls.length, historyItems.length);
-
-      // Don't assume anything about the order of history records in
-      // |historyItems|.
-      var firstUrlTime = Math.min(historyItems[0].lastVisitTime,
-                                  historyItems[1].lastVisitTime);
-      var secondUrlTime = Math.max(historyItems[0].lastVisitTime,
-                                   historyItems[1].lastVisitTime);
-
-      callback({
-        before: firstUrlTime - 100.0,
-        between: (firstUrlTime + secondUrlTime) / 2.0,
-        after: secondUrlTime + 100.0
+      console.log(" 1: historyItems = " + JSON.stringify(historyItems, null, 2));
+
+      waitAFewSeconds(1, function() {
+        chrome.history.search({text: ''}, function(historyItems) {
+          console.log(" 2: historyItems = " + JSON.stringify(historyItems, null, 2));
+
+          assertEq(urls.length, historyItems.length);
+
+          // Don't assume anything about the order of history records in
+          // |historyItems|.
+          var firstUrlTime = Math.min(historyItems[0].lastVisitTime,
+                                      historyItems[1].lastVisitTime);
+          var secondUrlTime = Math.max(historyItems[0].lastVisitTime,
+                                       historyItems[1].lastVisitTime);
+
+          callback({
+            before: firstUrlTime - 100.0,
+            between: (firstUrlTime + secondUrlTime) / 2.0,
+            after: secondUrlTime + 100.0
+          });
+        });
       });
     });
   });