diff --git a/runbot_merge/github.py b/runbot_merge/github.py index f8d9e2f0..89aa6257 100644 --- a/runbot_merge/github.py +++ b/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) - if head != sha: - _logger.error("Sanity check ref update of %s, expected %s got %s", - branch, sha, head - ) + @utils.backoff(exc=exceptions.FastForwardError) + def _wait_for_update(): + if not self._check_updated(branch, sha): + 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) - assert head == sha, "Sanity check ref update of %s, expected %s got %s" % ( - branch, sha, head - ) + @utils.backoff(exc=AssertionError) + def _wait_for_update(): + 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) - assert head == sha, "Sanity check ref update of %s, expected %s got %s" % ( - branch, sha, head - ) + @utils.backoff(exc=AssertionError) + def _wait_for_update(): + 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): diff --git a/runbot_merge/models/pull_requests.py b/runbot_merge/models/pull_requests.py index 1c98e074..a33962ef 100644 --- a/runbot_merge/models/pull_requests.py +++ b/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 = [0, 10, 10, 10, 10] +WAIT_FOR_VISIBILITY = [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 - for i, t in enumerate(WAIT_FOR_VISIBILITY): - time.sleep(t) + i = itertools.count() + @utils.backoff(delays=WAIT_FOR_VISIBILITY, exc=TimeoutError) + 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)) diff --git a/runbot_merge/utils.py b/runbot_merge/utils.py index ea2a9de3..6ef1c10d 100644 --- a/runbot_merge/utils.py +++ b/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)