[IMP] runbot_merge: error reporting

Largely informed by sentry,

- Fix an inconsistency in staging ref verification, `set_ref`
  internally waits for the observed head to match the requested head,
  but then `try_staging` would re-check that and immediately fail if
  it didn't.

  Because github is *eventually* consistent (hopefully) this second
  check can fail (and is also an extra API call), breaking staging
  unnecessarily, especially as we're still going to wait for the
  update to be visible to git.

  Remove this redundant check entirely, as github provides no way to
  ensure we have a consistent view of anything, it doesn't have much
  value and can do much harm.
- Add github request id to one of the sanity check warnings as that
  could be a useful thing to send upstream, missing github request ids
  in the future should be noted and added.
- Reworked the GH object's calls to be clearer and more coherent:
  consistently log the same thing on all GH errors (if `check`),
  rather than just on the one without a `check` entry.

  Also remove `raise_for_status` and raise `HTTPError` by hand every
  time we hit a status >= 400, so we always forward the response body
  no matter what its type is.
- Try again to log the request body (in full as it should be pretty
  small), also remove stripping since we specifically wanted to add a
  newline at the start, I've no idea what I was thinking.

Fixes #735, #764, #544

runbot_merge/github.py

@@ -1,12 +1,11 @@
 import collections.abc
 import itertools
-import json as json_
+import json
 import logging
 import logging.handlers
 import os
 import pathlib
 import pprint
-import textwrap
 import unicodedata
 
 import requests
@@ -47,7 +46,7 @@ def _init_gh_logger():
 if odoo.netsvc._logger_init:
     _init_gh_logger()
 
-GH_LOG_PATTERN = """=> {method} /{self._repo}/{path}{qs}{body}
+GH_LOG_PATTERN = """=> {method} /{path}{qs}{body}
 
 <= {r.status_code} {r.reason}
 {headers}
@@ -62,7 +61,7 @@ class GH(object):
         session.headers['Authorization'] = 'token {}'.format(token)
         session.headers['Accept'] = 'application/vnd.github.symmetra-preview+json'
 
-    def _log_gh(self, logger, method, path, params, json, response, level=logging.INFO):
+    def _log_gh(self, logger: logging.Logger, response: requests.Response, level: int = logging.INFO, extra=None):
         """ Logs a pair of request / response to github, to the specified
         logger, at the specified level.
 
@@ -70,11 +69,14 @@ class GH(object):
         bodies, at least in part) so we have as much information as possible
         for post-mortems.
         """
-        body = body2 = ''
+        req = response.request
+        url = werkzeug.urls.url_parse(req.url)
+        if url.netloc is not 'api.github.com':
+            return
 
-        if json:
-            body = '\n' + textwrap.indent('\t', pprint.pformat(json, indent=4))
+        body = '' if not req.body else ('\n' + pprint.pformat(json.loads(req.body.decode()), indent=4))
 
+        body2 = ''
         if response.content:
             if _is_json(response):
                 body2 = pprint.pformat(response.json(), depth=4)
@@ -87,19 +89,15 @@ class GH(object):
                 )
 
         logger.log(level, GH_LOG_PATTERN.format(
-            self=self,
             # requests data
-            method=method, path=path,
-            qs='' if not params else ('?' + werkzeug.urls.url_encode(params)),
-            body=utils.shorten(body.strip(), 400),
+            method=req.method, path=url.path, qs=url.query, body=body,
             # response data
             r=response,
             headers='\n'.join(
                 '\t%s: %s' % (h, v) for h, v in response.headers.items()
             ),
             body2=utils.shorten(body2.strip(), 400)
-        ))
-        return body2
+        ), extra=extra)
 
     def __call__(self, method, path, params=None, json=None, check=True):
         """
@@ -107,21 +105,21 @@ class GH(object):
         """
         path = f'/repos/{self._repo}/{path}'
         r = self._session.request(method, self._url + path, params=params, json=json)
-        self._log_gh(_gh, method, path, params, json, r)
+        self._log_gh(_gh, r)
         if check:
-            if isinstance(check, collections.abc.Mapping):
-                exc = check.get(r.status_code)
-                if exc:
-                    raise exc(r.text)
-            if r.status_code >= 400:
-                body = self._log_gh(
-                    _logger, method, path, params, json, r, level=logging.ERROR)
-                if not isinstance(body, (bytes, str)):
-                    raise requests.HTTPError(
-                        json_.dumps(body, indent=4),
-                        response=r
-                    )
-            r.raise_for_status()
+            try:
+                if isinstance(check, collections.abc.Mapping):
+                    exc = check.get(r.status_code)
+                    if exc:
+                        raise exc(r.text)
+                if r.status_code >= 400:
+                    raise requests.HTTPError(r.text, response=r)
+            except Exception:
+                self._log_gh(_logger, r, level=logging.ERROR, extra={
+                    'github-request-id': r.headers.get('x-github-request-id'),
+                })
+                raise
+
         return r
 
     def user(self, username):
@@ -180,13 +178,17 @@ class GH(object):
         if r.status_code == 200:
             head = r.json()['object']['sha']
         else:
-            head = '<Response [%s]: %s)>' % (r.status_code, r.json() if _is_json(r) else r.text)
+            head = '<Response [%s]: %s)>' % (r.status_code, r.text)
 
         if head == to:
             _logger.debug("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)
+        _logger.warning(
+            "Sanity check ref update of %s, expected %s got %s (response-id %s)",
+            branch, to, head,
+            r.headers.get('x-github-request-id')
+        )
         return head
 
     def fast_forward(self, branch, sha):

runbot_merge/models/pull_requests.py

@@ -463,13 +463,6 @@ For-Commit-Id: %s
             )
             refname = 'staging.{}'.format(self.name)
             it['gh'].set_ref(refname, staging_head)
-            # asserts that the new head is visible through the api
-            head = it['gh'].head(refname)
-            assert head == staging_head,\
-                "[api] updated %s:%s to %s but found %s" % (
-                    r.name, refname,
-                    staging_head, head,
-                )
 
             i = itertools.count()
             @utils.backoff(delays=WAIT_FOR_VISIBILITY, exc=TimeoutError)