[IMP] runbot_merge: use exponential backoff on head check

It's a waste to lose the entire staging if it's only a short blip /
delay thing, so retry multiple times. Add utility function to make
backoff functions easier (though the UI is not great ATM).

Also log the "left" parent of a merge commit (which should be the
"base") when creating it, for additional post-mortem information.

runbot_merge/github.py

@@ -110,15 +110,26 @@ class GH(object):
 
         _logger.debug('change_tags(%s, %s, from=%s, to=%s)', self._repo, pr, tags_before, tags_after)
 
+    def _check_updated(self, branch, to):
+        """
+        :return: nothing if successful, the incorrect HEAD otherwise
+        """
+        head = self.head(branch)
+        if head == to:
+            _logger.info("Sanity check ref update of %s to %s: ok", branch, to)
+            return
+
+        _logger.warning("Sanity check ref update of %s, expected %s got %s", branch, to, head)
+        return head
+
     def fast_forward(self, branch, sha):
         try:
             self('patch', 'git/refs/heads/{}'.format(branch), json={'sha': sha})
             _logger.debug('fast_forward(%s, %s, %s) -> OK', self._repo, branch, sha)
-            head = self.head(branch)
+            @utils.backoff(exc=exceptions.FastForwardError)
-            if head != sha:
+            def _wait_for_update():
-                _logger.error("Sanity check ref update of %s, expected %s got %s",
+                if not self._check_updated(branch, sha):
-                    branch, sha, head
+                    return
-                )
                 raise exceptions.FastForwardError(self._repo)
         except requests.HTTPError:
             _logger.debug('fast_forward(%s, %s, %s) -> ERROR', self._repo, branch, sha, exc_info=True)
@@ -138,10 +149,12 @@ class GH(object):
             'OK' if status0 == 200 else r.text or r.reason
         )
         if status0 == 200:
-            head = self.head(branch)
+            @utils.backoff(exc=AssertionError)
-            assert head == sha, "Sanity check ref update of %s, expected %s got %s" % (
+            def _wait_for_update():
-                branch, sha, head
+                head = self._check_updated(branch, sha)
-            )
+                assert not head, "Sanity check ref update of %s, expected %s got %s" % (
+                    branch, sha, head
+                )
             return
 
         # 422 makes no sense but that's what github returns, leaving 404 just
@@ -160,10 +173,12 @@ class GH(object):
                 'OK' if status1 == 201 else r.text or r.reason
             )
             if status1 == 201:
-                head = self.head(branch)
+                @utils.backoff(exc=AssertionError)
-                assert head == sha, "Sanity check ref update of %s, expected %s got %s" % (
+                def _wait_for_update():
-                    branch, sha, head
+                    head = self._check_updated(branch, sha)
-                )
+                    assert not head, "Sanity check ref update of %s, expected %s got %s" % (
+                        branch, sha, head
+                    )
                 return
 
         raise AssertionError("set_ref failed(%s, %s)" % (status0, status1))
@@ -178,7 +193,11 @@ class GH(object):
             r = r.json()
         except Exception:
             raise exceptions.MergeError("Got non-JSON reponse from github: %s %s (%s)" % (r.status_code, r.reason, r.text))
-        _logger.debug("merge(%s, %s, %s) -> %s", self._repo, dest, shorten(message), r['sha'])
+        _logger.debug(
+            "merge(%s, %s (%s), %s) -> %s",
+            self._repo, dest, r['parents'][0]['sha'],
+            shorten(message), r['sha']
+        )
         return dict(r['commit'], sha=r['sha'])
 
     def rebase(self, pr, dest, reset=False, commits=None):

runbot_merge/models/pull_requests.py

@@ -2,6 +2,7 @@ import base64
 import collections
 import datetime
 import io
+import itertools
 import json
 import logging
 import os
@@ -21,8 +22,7 @@ from odoo.tools import OrderedSet
 
 from .. import github, exceptions, controllers, utils
 
-STAGING_SLEEP = True # actually a flag now (whether to loop around waiting for visibility on the remote
+WAIT_FOR_VISIBILITY = [10, 10, 10, 10]
-WAIT_FOR_VISIBILITY = [0, 10, 10, 10, 10]
 
 _logger = logging.getLogger(__name__)
 class Project(models.Model):
@@ -402,25 +402,22 @@ class Branch(models.Model):
                     r.name, refname,
                     staging_head, head,
                 )
-            if not STAGING_SLEEP:
-                continue
 
-            # waits for the new head to be visible through the repo itself
+            i = itertools.count()
-            for i, t in enumerate(WAIT_FOR_VISIBILITY):
+            @utils.backoff(delays=WAIT_FOR_VISIBILITY, exc=TimeoutError)
-                time.sleep(t)
+            def wait_for_visibility():
                 if self._check_visibility(r, refname, staging_head, token):
                     _logger.info(
                         "[repo] updated %s:%s to %s: ok (at %d/%d)",
                         r.name, refname, staging_head,
-                        i, len(WAIT_FOR_VISIBILITY)
+                        next(i), len(WAIT_FOR_VISIBILITY)
                     )
-                    break
+                    return
                 _logger.warning(
                     "[repo] updated %s:%s to %s: failed (at %d/%d)",
                     r.name, refname, staging_head,
-                    i, len(WAIT_FOR_VISIBILITY)
+                    next(i), len(WAIT_FOR_VISIBILITY)
                 )
-            else: # if we never saw the update... cancel the staging?
                 raise TimeoutError("Staged head not updated after %d seconds" % sum(WAIT_FOR_VISIBILITY))
 
 

runbot_merge/utils.py

@@ -1,4 +1,7 @@
 # -*- coding: utf-8 -*-
+import itertools
+import time
+
 
 def shorten(text_ish, length):
     """ If necessary, cuts-off the text or bytes input and appends ellipsis to
@@ -14,3 +17,16 @@ def shorten(text_ish, length):
         cont = cont.encode('ascii') # whatever
     # add enough room for the ellipsis
     return text_ish[:length-3] + cont
+
+BACKOFF_DELAYS = (0.1, 0.2, 0.4, 0.8, 1.6)
+def backoff(func=None, *, delays=BACKOFF_DELAYS, exc=Exception):
+    if func is None:
+        return lambda func: backoff(func, delays=delays, exc=exc)
+
+    for delay in itertools.chain(delays, [None]):
+        try:
+            return func()
+        except exc:
+            if delay is None:
+                raise
+            time.sleep(delay)