From cd4ded899b56ded376824a117bfaa444b39f8c92 Mon Sep 17 00:00:00 2001 From: Xavier Morel Date: Tue, 13 Jun 2023 14:22:40 +0200 Subject: [PATCH] [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 | 60 ++++++++++++++-------------- runbot_merge/models/pull_requests.py | 7 ---- 2 files changed, 31 insertions(+), 36 deletions(-) diff --git a/runbot_merge/github.py b/runbot_merge/github.py index 27cf6305..4f2b6fc8 100644 --- a/runbot_merge/github.py +++ b/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 = '' % (r.status_code, r.json() if _is_json(r) else r.text) + head = '' % (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): diff --git a/runbot_merge/models/pull_requests.py b/runbot_merge/models/pull_requests.py index 8e7cc1f5..a25b3cd2 100644 --- a/runbot_merge/models/pull_requests.py +++ b/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)