Avoid dependance on timing in flaky history tests. Add logging to understand waterfall failures.

BUG=26296
TEST=ExtensionHistoryApiTest.*

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

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

8 files changed, 222 insertions, 146 deletions

diff --git a/chrome/browser/extensions/extension_history_apitest.cc b/chrome/browser/extensions/extension_history_apitest.cc
index 6bac7bc..a0b3fbe 100644
--- a/chrome/browser/extensions/extension_history_apitest.cc
+++ b/chrome/browser/extensions/extension_history_apitest.cc
@@ -2,6 +2,7 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+#include "base/base_switches.h"
 #include "base/command_line.h"
 #include "chrome/browser/extensions/extension_apitest.h"
 #include "net/base/mock_host_resolver.h"
@@ -16,6 +17,17 @@ class ExtensionHistoryApiTest : public ExtensionApiTest {
 
     ASSERT_TRUE(StartTestServer());
   }
+
+  virtual void SetUpCommandLine(CommandLine* command_line) {
+    ExtensionApiTest::SetUpCommandLine(command_line);
+
+    // Tests are flaky, but only on the waterfall (crbug.com/26296).
+    // Failures involve a call to chrome.history.search() not finding
+    // a result whose addition caused event chrome.history.onVisited
+    // to fire.  Turn on verbose logging.
+    // TODO(skerner): Remove this once the flakiness is fixed.
+    command_line->AppendSwitchASCII(switches::kVModule, "*/history/*=1");
+  }
 };
 
 // Flaky, http://crbug.com/26296.
diff --git a/chrome/browser/history/expire_history_backend.cc b/chrome/browser/history/expire_history_backend.cc
index 8cafc82..62aa7e5 100644
--- a/chrome/browser/history/expire_history_backend.cc
+++ b/chrome/browser/history/expire_history_backend.cc
@@ -557,7 +557,8 @@ void ExpireHistoryBackend::ArchiveURLsAndVisits(
     cur_visit.url_id = main_id_to_archived_id[cur_visit.url_id];
     cur_visit.referring_visit = 0;
     VisitSourceMap::iterator iter = visit_sources.find(visits[i].visit_id);
-    archived_db_->AddVisit(&cur_visit,
+    archived_db_->AddVisit(
+        &cur_visit,
         iter == visit_sources.end() ? SOURCE_BROWSED : iter->second);
     // Ignore failures, we will delete it from the main DB no matter what.
   }
diff --git a/chrome/browser/history/history_backend.cc b/chrome/browser/history/history_backend.cc
index a02d3e9..50f47d5 100644
--- a/chrome/browser/history/history_backend.cc
+++ b/chrome/browser/history/history_backend.cc
@@ -721,6 +721,9 @@ std::pair<URLID, VisitID> HistoryBackend::AddPageVisit(
     // Re-enable this.
     // GetMostRecentRedirectsTo(url, &details->redirects);
     BroadcastNotifications(NotificationType::HISTORY_URL_VISITED, details);
+  } else {
+    VLOG(0) << "Failed to build visit insert statement:  "
+            << "url_id = " << url_id;
   }
 
   return std::make_pair(url_id, visit_id);
@@ -1203,10 +1206,18 @@ void HistoryBackend::QueryHistoryBasic(URLDatabase* url_db,
     const VisitRow visit = visits[i];
 
     // Add a result row for this visit, get the URL info from the DB.
-    if (!url_db->GetURLRow(visit.url_id, &url_result))
+    if (!url_db->GetURLRow(visit.url_id, &url_result)) {
+      VLOG(0) << "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())
+    }
+
+    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();
       continue;  // Don't report invalid URLs in case of corruption.
+    }
 
     // The archived database may be out of sync with respect to starring,
     // titles, last visit date, etc. Therefore, we query the main DB if the
diff --git a/chrome/browser/history/url_database.cc b/chrome/browser/history/url_database.cc
index b6246fe..24decc6 100644
--- a/chrome/browser/history/url_database.cc
+++ b/chrome/browser/history/url_database.cc
@@ -163,8 +163,11 @@ URLID URLDatabase::AddURLInternal(const history::URLRow& info,
   statement.BindInt(5, info.hidden() ? 1 : 0);
   statement.BindInt64(6, info.favicon_id());
 
-  if (!statement.Run())
+  if (!statement.Run()) {
+    VLOG(0) << "Failed to add url " << info.url().possibly_invalid_spec()
+            << " to table history.urls.";
     return 0;
+  }
   return GetDB().GetLastInsertRowId();
 }
 
diff --git a/chrome/browser/history/visit_database.cc b/chrome/browser/history/visit_database.cc
index d0156c2..ace5dac 100644
--- a/chrome/browser/history/visit_database.cc
+++ b/chrome/browser/history/visit_database.cc
@@ -111,8 +111,11 @@ VisitID VisitDatabase::AddVisit(VisitRow* visit, VisitSource source) {
       "INSERT INTO visits "
       "(url, visit_time, from_visit, transition, segment_id, is_indexed) "
       "VALUES (?,?,?,?,?,?)"));
-  if (!statement)
+  if (!statement) {
+    VLOG(0) << "Failed to build visit insert statement:  "
+            << "url_id = " << visit->url_id;
     return 0;
+  }
 
   statement.BindInt64(0, visit->url_id);
   statement.BindInt64(1, visit->visit_time.ToInternalValue());
@@ -120,8 +123,12 @@ VisitID VisitDatabase::AddVisit(VisitRow* visit, VisitSource source) {
   statement.BindInt64(3, visit->transition);
   statement.BindInt64(4, visit->segment_id);
   statement.BindInt64(5, visit->is_indexed);
-  if (!statement.Run())
+
+  if (!statement.Run()) {
+    VLOG(0) << "Failed to execute visit insert statement:  "
+            << "url_id = " << visit->url_id;
     return 0;
+  }
 
   visit->visit_id = GetDB().GetLastInsertRowId();
 
@@ -129,13 +136,19 @@ VisitID VisitDatabase::AddVisit(VisitRow* visit, VisitSource source) {
     // Record the source of this visit when it is not browsed.
     sql::Statement statement1(GetDB().GetCachedStatement(SQL_FROM_HERE,
         "INSERT INTO visit_source (id, source) VALUES (?,?)"));
-    if (!statement1.is_valid())
+    if (!statement1.is_valid()) {
+      VLOG(0) << "Failed to build visit_source insert statement:  "
+              << "url_id = " << visit->visit_id;
       return 0;
+    }
 
     statement1.BindInt64(0, visit->visit_id);
     statement1.BindInt64(1, source);
-    if (!statement1.Run())
+    if (!statement1.Run()) {
+      VLOG(0) << "Failed to execute visit_source insert statement:  "
+              << "url_id = " << visit->visit_id;
       return 0;
+    }
   }
 
   return visit->visit_id;
diff --git a/chrome/test/data/extensions/api_test/history/common.js b/chrome/test/data/extensions/api_test/history/common.js
index 0bb8b47..e3eeb8e 100644
--- a/chrome/test/data/extensions/api_test/history/common.js
+++ b/chrome/test/data/extensions/api_test/history/common.js
@@ -1,6 +1,7 @@
 var pass = chrome.test.callbackPass;
 var fail = chrome.test.callbackFail;
 var assertEq = chrome.test.assertEq;
+var assertTrue = chrome.test.assertTrue;
 
 var GOOGLE_URL = 'http://www.google.com/';
 var PICASA_URL = 'http://www.picasa.com/';
@@ -128,3 +129,46 @@ function runHistoryTestFns(testFns) {
     chrome.test.runTests(testFns);
   });
 }
+
+/**
+ * Add two URLs to the history.  Compute three times, in ms since the epoch:
+ *    'before': A time before both URLs were added.
+ *    'between': A time between the times teh URLs were added.
+ *    'after': A time after both were added.
+ * All times are passed to |callback| as properties of its object parameter.
+ * @param {Array.<string>} urls An array of two URLs to add to the history.
+ * @param {function(object)} callback Called with the times described above.
+ */
+function addUrlsWithTimeline(urls, callback) {
+  // If a test needs more than two urls, this could be generalized.
+  assertEq(2, urls.length);
+
+  // Add the first URL now.
+  chrome.history.addUrl({url: urls[0]});
+
+  // Add the second URL after a delay, so that the times at which the
+  // URLs were added are not the same.
+  waitAFewSeconds(1, function() {
+    chrome.history.addUrl({url: urls[1]});
+
+    // Use search to get the times of the two URLs, and compute times
+    // 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
+      });
+    });
+  });
+}
diff --git a/chrome/test/data/extensions/api_test/history/delete.js b/chrome/test/data/extensions/api_test/history/delete.js
index 2ca908b..de91069 100644
--- a/chrome/test/data/extensions/api_test/history/delete.js
+++ b/chrome/test/data/extensions/api_test/history/delete.js
@@ -46,11 +46,11 @@ runHistoryTestFns([
     });
   },
 
+  // Suppose we have time epochs x,y,z and history events A,B which occur
+  // in the sequence x A y B z.  Delete range [x,y], check that only A is
+  // removed.
   function deleteStartRange() {
     var urls = [GOOGLE_URL, PICASA_URL];
-    var startDate = {};
-    var endDate = {};
-    var itemsAdded = 0;
 
     function deleteRangeTestVerification() {
       removeItemRemovedListener();
@@ -65,47 +65,25 @@ runHistoryTestFns([
       });
     }
 
-    function onAddedItem() {
-      itemsAdded += 1;
-
-      if (itemsAdded < urls.length) {
-        // Chrome has seconds resolution, so we must wait to search a range.
-        waitAFewSeconds(2, function() {
-          endDate = new Date();
-          endDate.setTime(endDate.getTime() - 1000);
-          populateHistory([urls[itemsAdded]], function() { });
-        });
-        return;
-      }
-
-      removeItemVisitedListener();
-      chrome.history.deleteRange({ 'startTime': startDate.getTime(),
-                                   'endTime': endDate.getTime() },
-                                 function() { });
-    }
-
-    // deletRange entry point.
     chrome.history.deleteAll(function() {
-      setItemVisitedListener(onAddedItem);
       setItemRemovedListener(deleteRangeTestVerification);
-
-      startDate = new Date();
-      startDate.setTime(startDate.getTime() - 1000);
-
-      populateHistory([urls[itemsAdded]], function() { });
+      addUrlsWithTimeline(urls, function(eventTimes) {
+        // Remove the range covering the first URL:
+        chrome.history.deleteRange(
+          {'startTime': eventTimes.before,
+           'endTime': eventTimes.between},
+          function() {});
+      });
     });
   },
 
   // Suppose we have time epochs x,y,z and history events A,B which occur
-  // in the sequence x A y B z.  The previous deleteRange test deleted the
-  // range [x,y], this test deletes the range [y,z].
+  // in the sequence x A y B z.  Delete range [y,z], check that only B is
+  // removed.
   function deleteEndRange() {
     var urls = [GOOGLE_URL, PICASA_URL];
-    var startDate = {};
-    var endDate = {};
-    var itemsAdded = 0;
 
-    function deleteRange2TestVerification() {
+    function deleteRangeTestVerification() {
       removeItemRemovedListener();
 
       var query = { 'text': '' };
@@ -118,33 +96,76 @@ runHistoryTestFns([
       });
     }
 
-    function onAddedItem() {
-      itemsAdded += 1;
-
-      if (itemsAdded < urls.length) {
-        // Chrome has seconds resolution, so we must wait to search a range.
-        waitAFewSeconds(2, function() {
-          startDate = new Date();
-          startDate.setTime(startDate.getTime() - 1000);
-          populateHistory([urls[itemsAdded]], function() { });
-        });
-        return;
-      }
+    chrome.history.deleteAll(function() {
+      setItemRemovedListener(deleteRangeTestVerification);
+      addUrlsWithTimeline(urls, function(eventTimes) {
+        // Remove the range covering the second URL:
+        chrome.history.deleteRange(
+          {'startTime': eventTimes.between,
+           'endTime': eventTimes.after},
+          function() {});
+      });
+    });
+  },
 
-      removeItemVisitedListener();
+  // Suppose we have time epochs x,y,z and history events A,B which occur
+  // in the sequence x A y B z.  Delete range [x,z], check that both A
+  // and B are removed.
+  function deleteWholeRange() {
+    var urls = [GOOGLE_URL, PICASA_URL];
+
+    function deleteRangeTestVerification() {
+      removeItemRemovedListener();
 
-      endDate = new Date();
-      endDate.setTime(endDate.getTime() + 1000);
-      chrome.history.deleteRange({'startTime': startDate.getTime(),
-                                  'endTime': endDate.getTime() },
-                                  function() { });
+      var query = { 'text': '' };
+      chrome.history.search(query, function(results) {
+        assertEq(0, results.length);
+
+        // The test has succeeded.
+        chrome.test.succeed();
+      });
     }
 
-    // deletRange entry point.
     chrome.history.deleteAll(function() {
-      setItemVisitedListener(onAddedItem);
-      setItemRemovedListener(deleteRange2TestVerification);
-      populateHistory([urls[itemsAdded]], function() { });
+      setItemRemovedListener(deleteRangeTestVerification);
+      addUrlsWithTimeline(urls, function(eventTimes) {
+        // Remove the range covering both URLs:
+        chrome.history.deleteRange(
+          {'startTime': eventTimes.before,
+           'endTime': eventTimes.after},
+          function() {});
+      });
     });
   },
+
+  // Delete a range with start time equal to end time.  See that nothing
+  // is removed.
+  function deleteEmptyRange() {
+    var urls = [GOOGLE_URL, PICASA_URL];
+
+    function deleteRangeTestVerification() {
+      removeItemRemovedListener();
+
+      // Nothing should have been deleted.
+      chrome.test.fail();
+    }
+
+    chrome.history.deleteAll(function() {
+      setItemRemovedListener(deleteRangeTestVerification);
+      addUrlsWithTimeline(urls, function(eventTimes) {
+        // Remove an empty range.
+        chrome.history.deleteRange(
+          {'startTime': eventTimes.between,
+           'endTime': eventTimes.between},
+          function() {
+            var query = { 'text': '' };
+            chrome.history.search(query, function(results) {
+              // Nothing should have been deleted.
+              assertEq(2, results.length);
+              chrome.test.succeed();
+            });
+          });
+      });
+    });
+  }
 ]);
diff --git a/chrome/test/data/extensions/api_test/history/timed_search.js b/chrome/test/data/extensions/api_test/history/timed_search.js
index cab94b2..2534d02 100644
--- a/chrome/test/data/extensions/api_test/history/timed_search.js
+++ b/chrome/test/data/extensions/api_test/history/timed_search.js
@@ -3,46 +3,62 @@
 
 // runHistoryTestFns is defined in ./common.js .
 runHistoryTestFns([
-  function timeScopedSearch() {
-    var startDate = {};
-    var endDate = {};
-
-    function timeScopedSearchTestVerification() {
-      removeItemVisitedListener();
-
-      var query = { 'text': '',
-                    'startTime': startDate.getTime(),
-                    'endTime': endDate.getTime() };
-       chrome.history.search(query, function(results) {
-         assertEq(1, results.length);
-         assertEq(GOOGLE_URL, results[0].url);
-
-        // The test has succeeded.
-        chrome.test.succeed();
+  // Give time epochs x,y,z and history events A,B which occur in the sequence
+  // x A y B z, test that searching in [x,y] finds only A.
+  function timeScopedSearchStartRange() {
+    var urls = [GOOGLE_URL, PICASA_URL];
+    chrome.history.deleteAll(function() {
+      addUrlsWithTimeline(urls, function(eventTimes) {
+        // Remove the range covering the first URL:
+        chrome.history.search(
+          {'text': '',
+           'startTime': eventTimes.before,
+           'endTime': eventTimes.between},
+          function(historyItems) {
+            assertEq(1, historyItems.length);
+            assertEq(GOOGLE_URL, historyItems[0].url);
+            chrome.test.succeed();
+          });
       });
-    };
-
-    function onAddedItem() {
-      // Set the next test callback.
-      setNextItemVisitedListener(timeScopedSearchTestVerification);
+    });
+  },
 
-      // Chrome has seconds resolution, so we must wait in order to search
-      // a range.
-      waitAFewSeconds(2, function() {
-        endDate = new Date();
-        endDate.setTime(endDate.getTime() - 500);
-        populateHistory([PICASA_URL], function() { });
+  // Give time epochs x,y,z and history events A,B which occur in the sequence
+  // x A y B z, test that searching in [y,z] finds only B.
+  function timeScopedSearchEndRange() {
+    var urls = [GOOGLE_URL, PICASA_URL];
+    chrome.history.deleteAll(function() {
+      addUrlsWithTimeline(urls, function(eventTimes) {
+        // Remove the range covering the first URL:
+        chrome.history.search(
+          {'text': '',
+           'startTime': eventTimes.between,
+           'endTime': eventTimes.end},
+          function(historyItems) {
+            assertEq(1, historyItems.length);
+            assertEq(PICASA_URL, historyItems[0].url);
+            chrome.test.succeed();
+          });
       });
-    };
+    });
+  },
 
-    // timeScopedSearch entry point.
+  // Give time epochs x,y,z and history events A,B which occur in the sequence
+  // x A y B z, test that searching in [y,y] finds nothing.
+  function timeScopedSearchEmptyRange() {
+    var urls = [GOOGLE_URL, PICASA_URL];
     chrome.history.deleteAll(function() {
-      // Set the test callback.
-      setItemVisitedListener(onAddedItem);
-      // Set the start time a few seconds in the past.
-      startDate = new Date();
-      startDate.setTime(startDate.getTime() - 1000);
-      populateHistory([GOOGLE_URL], function() { });
+      addUrlsWithTimeline(urls, function(eventTimes) {
+        // Remove the range covering the first URL:
+        chrome.history.search(
+          {'text': '',
+           'startTime': eventTimes.between,
+           'endTime': eventTimes.between},
+          function(historyItems) {
+            assertEq(0, historyItems.length);
+            chrome.test.succeed();
+          });
+      });
     });
   },
 
@@ -51,56 +67,11 @@ runHistoryTestFns([
       // Search with an integer time range.
       var query = { 'text': '',
                     'startTime': 0,
-                    'endTime': 12345678 };
+                    'endTime': 123456789 };
       chrome.history.search(query, function(results) {
         assertEq(0, results.length);
         chrome.test.succeed();
       });
     });
-  },
-
-  // Give time epochs x,y,z and history events A,B which occur in the sequence
-  // x A y B z, this test scopes the search to the interval [y,z] to test that
-  // [x,y) is excluded.  The previous test scoped to the interval [x,y].
-  function timeScopedSearch2() {
-    var startDate = {};
-    var endDate = {};
-
-    function timeScopedSearch2TestVerification() {
-      removeItemVisitedListener();
-
-      endDate = new Date();
-      endDate.setTime(endDate.getTime() + 1000);
-      var query = { 'text': '',
-                    'startTime': startDate.getTime(),
-                    'endTime': endDate.getTime() };
-       chrome.history.search(query, function(results) {
-         assertEq(1, results.length);
-         assertEq(PICASA_URL, results[0].url);
-
-        // The test has succeeded.
-        chrome.test.succeed();
-      });
-    }
-
-    function onAddedItem() {
-      // Set the next test callback.
-      setNextItemVisitedListener(timeScopedSearch2TestVerification);
-
-      // Chrome has seconds resolution, so we must wait in order to search
-      // a range.
-      waitAFewSeconds(2, function() {
-        startDate = new Date();
-        startDate.setTime(startDate.getTime() - 1000);
-        populateHistory([PICASA_URL], function() { });
-      });
-    };
-
-    // timeScopedSearch entry point.
-    chrome.history.deleteAll(function() {
-      // Set the test callback.
-      setItemVisitedListener(onAddedItem);
-      populateHistory([GOOGLE_URL], function() { });
-    });
   }
 ]);