detect when changes have been re-queued by developer

This CL teaches the pre-cq-launcher to detect when a CL that was
previously rejected has been re-queued in the CQ, and to record a
timestamped CL action when this takes place. The rationale for doing
this in the pre-cq-launcher is that that builder is continuously running
and examining the validation pool.

BUG=chromium:424037
TEST=New unit test

Change-Id: I393ec4374885669fa20d230da3c03e2387834d5f
Reviewed-on: https://chromium-review.googlesource.com/225865
Reviewed-by: Aviv Keshet <akeshet@chromium.org>
Commit-Queue: Aviv Keshet <akeshet@chromium.org>
Tested-by: Aviv Keshet <akeshet@chromium.org>

4 files changed, 103 insertions, 22 deletions

diff --git a/cbuildbot/constants.py b/cbuildbot/constants.py
index e992c09df..ed5bf635f 100644
--- a/cbuildbot/constants.py
+++ b/cbuildbot/constants.py
@@ -483,9 +483,14 @@ CL_ACTION_PRE_CQ_WAITING = 'pre_cq_waiting'
 CL_ACTION_PRE_CQ_READY_TO_SUBMIT = 'pre_cq_ready_to_submit'
 
 # Miscellaneous actions
-CL_ACTION_REQUEUED = 'requeued'           # Recorded for a change when it is
-                                          # noticed that a previously rejected
-                                          # patch is again in the queue.
+
+# Recorded by pre-cq launcher for a change when it is noticed that a previously
+# rejected change is again in the queue.
+# This is a best effort detection for developers re-marking their changes, to
+# help calculate true CQ handling time. It is susceptible to developers
+# un-marking their change after is requeued or to the CQ picking up a CL before
+# it is seen by the pre-cq-launcher.
+CL_ACTION_REQUEUED = 'requeued'
 
 # Recorded by pre-cq launcher when it has screened a change for necessary
 # tryjobs
diff --git a/cbuildbot/stages/sync_stages.py b/cbuildbot/stages/sync_stages.py
index 4f260171c..05c9da5b9 100644
--- a/cbuildbot/stages/sync_stages.py
+++ b/cbuildbot/stages/sync_stages.py
@@ -1111,11 +1111,18 @@ class PreCQLauncherStage(SyncStage):
     """
     # Get change status.
     status_map = {}
-    _, db = self._run.GetCIDBHandle()
+    build_id, db = self._run.GetCIDBHandle()
     action_history = db.GetActionsForChanges(changes)
     for change in changes:
       status = clactions.GetCLPreCQStatus(change, action_history)
       status_map[change] = status
+      # Detect changes that have been re-queued by the developer, and mark
+      # them as such in cidb.
+      was_requeued = clactions.WasChangeRequeued(change, action_history)
+      if was_requeued:
+        action = clactions.CLAction.FromGerritPatchAndAction(
+            change, constants.CL_ACTION_REQUEUED)
+        db.InsertCLActions(build_id, [action])
 
     # Launch trybots for manifest changes.
     for plan in self.GetDisjointTransactionsToTest(pool, changes, status_map):
diff --git a/cbuildbot/stages/sync_stages_unittest.py b/cbuildbot/stages/sync_stages_unittest.py
index be97b9524..efe51af2a 100755
--- a/cbuildbot/stages/sync_stages_unittest.py
+++ b/cbuildbot/stages/sync_stages_unittest.py
@@ -180,7 +180,7 @@ class BaseCQTestCase(generic_stages_unittest.StageTest):
   def PerformSync(self, committed=False, num_patches=1, tree_open=True,
                   tree_throttled=False,
                   pre_cq_status=constants.CL_STATUS_PASSED,
-                  runs=0, **kwargs):
+                  runs=0, changes=None, **kwargs):
     """Helper to perform a basic sync for master commit queue.
 
     Args:
@@ -194,6 +194,9 @@ class BaseCQTestCase(generic_stages_unittest.StageTest):
       runs: The maximum number of times to allow validation_pool.AcquirePool
             to wait for additional changes. runs=0 means never wait for
             additional changes. Default: 0.
+      changes: Optional list of MockPatch instances that should be available
+               in validation pool. If not specified, a set of |num_patches|
+               patches will be created.
       **kwargs: Additional arguments to pass to MockPatch when creating patches.
 
     Returns:
@@ -201,7 +204,7 @@ class BaseCQTestCase(generic_stages_unittest.StageTest):
     """
     kwargs.setdefault('approval_timestamp',
         time.time() - sync_stages.PreCQLauncherStage.LAUNCH_DELAY * 60)
-    changes = [MockPatch(**kwargs)] * num_patches
+    changes = changes or [MockPatch(**kwargs)] * num_patches
     if pre_cq_status is not None:
       new_build_id = self.fake_db.InsertBuild('Pre cq group',
                                               constants.WATERFALL_TRYBOT,
@@ -288,15 +291,18 @@ class MasterCQSyncTestCase(BaseCQTestCase):
     """
     return self._testCommitNonManifestChange(committed=False)
 
-  def _testCommitManifestChange(self, **kwargs):
+  def _testCommitManifestChange(self, changes=None, **kwargs):
     """Test committing a change to a project that's part of the manifest.
 
+    Args:
+      changes: Optional list of MockPatch instances to use in PerformSync.
+
     Returns:
       List of MockPatch objects that were used in PerformSync
     """
     self.PatchObject(validation_pool.ValidationPool, '_FilterNonCrosProjects',
                      side_effect=lambda x, _: (x, []))
-    return self.PerformSync(**kwargs)
+    return self.PerformSync(changes=changes, **kwargs)
 
   def _testDefaultSync(self):
     """Test basic ability to sync with standard options.
@@ -458,16 +464,20 @@ class PreCQLauncherStageTest(MasterCQSyncTestCase):
     action_history = self.fake_db.GetActionsForChanges([change])
     return clactions.GetCLPreCQStatus(change, action_history)
 
-  def runTrybotTest(self, launching=0, waiting=0, failed=0, runs=0):
+  def runTrybotTest(self, launching=0, waiting=0, failed=0, runs=0,
+                    change=None):
     """Helper function for testing PreCQLauncher.
 
-    Create a mock patch to be picked up by the PreCQ. Allow up to
-    |runs|+1 calls to ProcessChanges. Assert that the patch received status
-    LAUNCHING, WAITING, and FAILED |launching|, |waiting|, and |failed| times
-    respectively.
+    Create a mock patch to be picked up by the PreCQ (or use |change| if it is
+    specified. Allow up to |runs|+1 calls to ProcessChanges. Assert that the
+    patch received status LAUNCHING, WAITING, and FAILED |launching|,
+    |waiting|, and |failed| times respectively.
     """
-    change = self._testCommitManifestChange(pre_cq_status=None, runs=runs)[0]
-
+    changes = None
+    if change:
+      changes = [change]
+    change = self._testCommitManifestChange(changes=changes, pre_cq_status=None,
+                                            runs=runs)[0]
     # Count the number of recorded actions corresponding to launching, watiting,
     # and failed, and ensure they are correct.
     expected = (launching, waiting, failed)
@@ -512,6 +522,22 @@ class PreCQLauncherStageTest(MasterCQSyncTestCase):
     self.runTrybotTest(runs=1)
     m.assert_called_with([mock.ANY], check_tree_open=False)
 
+  def testRequeued(self):
+    """Test that a previously rejected patch gets marked as requeued."""
+    p = MockPatch()
+    previous_build_id = self.fake_db.InsertBuild(
+        'some name', constants.WATERFALL_TRYBOT, 1, 'some_config',
+        'some_hostname')
+    action = clactions.CLAction.FromGerritPatchAndAction(
+        p, constants.CL_ACTION_KICKED_OUT)
+    self.fake_db.InsertCLActions(previous_build_id, [action])
+    self.runTrybotTest(launching=1, change=p)
+
+    actions_for_patch = self.fake_db.GetActionsForChanges([p])
+    requeued_actions = [a for a in actions_for_patch
+                        if a.action == constants.CL_ACTION_REQUEUED]
+    self.assertEqual(1, len(requeued_actions))
+
 
 if __name__ == '__main__':
   cros_test_lib.main()
diff --git a/lib/clactions.py b/lib/clactions.py
index 9dd2ff1c0..e91f30aa6 100644
--- a/lib/clactions.py
+++ b/lib/clactions.py
@@ -122,22 +122,65 @@ def GetCLPreCQStatus(change, action_history):
   Returns:
     The status, as a string, or None if there is no recorded pre-cq status.
   """
+  actions_for_patch = ActionsForPatch(change, action_history)
+  actions_for_patch = [a for a in actions_for_patch
+                       if a.action in _PRECQ_ACTION_TO_STATUS]
+
+  if not actions_for_patch:
+    return None
+
+  return TranslatePreCQActionToStatus(actions_for_patch[-1].action)
+
+
+def ActionsForPatch(change, action_history):
+  """Filters a CL action list to only those for a given patch.
+
+  Args:
+    change: GerritPatch instance to filter for.
+    action_history: List of CLAction objects.
+  """
   patch_number = int(change.patch_number)
   change_number = int(change.gerrit_number)
   change_source = BoolToChangeSource(change.internal)
 
-  # Filter out actions to other patch numbers and actions that are not
-  # pre-cq status actions.
   actions_for_patch = [a for a in action_history
                        if a.change_source == change_source and
                           a.change_number == change_number and
-                          a.patch_number == patch_number and
-                          a.action in _PRECQ_ACTION_TO_STATUS]
+                          a.patch_number == patch_number]
 
-  if not actions_for_patch:
-    return None
+  return actions_for_patch
 
-  return TranslatePreCQActionToStatus(actions_for_patch[-1].action)
+
+def WasChangeRequeued(change, action_history):
+  """For a |change| that is ready, determine if it has been re-marked as such.
+
+  This method is meant to be used on a |change| that is currently marked as
+  CQ ready. It determines if |change| had been previously rejected but not
+  yet marked as requeued.
+
+  If this returns True, then a REQUEUED action should be separately recorded
+  for |change|.
+
+  Args:
+    change: GerritPatch instance to operate upon.
+    action_history: List of CL actions (may include actions on changes other
+                    than |change|).
+
+  Returns:
+    True is |change| has been re-marked as CQ ready by a developer, but
+    not yet marked as REQUEUED in its action history.
+  """
+  actions_for_patch = ActionsForPatch(change, action_history)
+
+  # Return True if the newest KICKED_OUT action is newer than the newest
+  # REQUEUED action.
+  for a in reversed(actions_for_patch):
+    if a.action == constants.CL_ACTION_KICKED_OUT:
+      return True
+    if a.action == constants.CL_ACTION_REQUEUED:
+      return False
+
+  return False
 
 
 def GetCLActionCount(change, configs, action, action_history,