From cabab210dee5229d5ea3e2686f1ca313bd220c2b Mon Sep 17 00:00:00 2001 From: Xavier Morel Date: Fri, 26 Jul 2024 14:48:59 +0200 Subject: [PATCH] [FIX] *: don't send merge errors to logging Merge errors are logical failures, not technical, it doesn't make sense to log them out because there's nothing to be done technically, a PR having consistency issues or a conflict is "normal". As such those messages are completely useless and just take unnecessary space in the logs, making their use more difficult. Instead of sending them to logging, log staging attempts to the PR itself, and only do normal logging of the operation as an indicative item. And remove a bunch of `expect_log_errors` which don't stand anymore. While at it, fix a missed issue in forward porting: if the `root.head` doesn't exist in the repo its `fetch` will immediately fail before `cat-file` can even run, so the second one is redundant and the first one needs to be handled properly. Do that. And leave checking for *that* specific condition as a logged-out error as it should mean there's something very odd with the repository (how can a pull request have a head we can't fetch?) --- forwardport/models/project.py | 21 +++++++++++---------- forwardport/tests/test_conflicts.py | 1 - forwardport/tests/test_limit.py | 1 - runbot_merge/github.py | 2 +- runbot_merge/models/pull_requests.py | 5 ++--- runbot_merge/models/stagings_create.py | 6 ++++-- runbot_merge/tests/test_basic.py | 5 ----- runbot_merge/tests/test_multirepo.py | 1 - runbot_merge/tests/test_oddities.py | 1 - 9 files changed, 18 insertions(+), 25 deletions(-) diff --git a/forwardport/models/project.py b/forwardport/models/project.py index 31e0ec9c..e6599975 100644 --- a/forwardport/models/project.py +++ b/forwardport/models/project.py @@ -299,23 +299,24 @@ class PullRequests(models.Model): "Forward-porting %s (%s) to %s", self.display_name, root.display_name, target_branch.name ) - tree = source.with_config(stdout=subprocess.PIPE, stderr=subprocess.STDOUT).fetch() - logger.info("Updated cache repo %s:\n%s", source._directory, tree.stdout.decode()) + fetch = source.with_config(stdout=subprocess.PIPE, stderr=subprocess.STDOUT).fetch() + logger.info("Updated cache repo %s:\n%s", source._directory, fetch.stdout.decode()) - tree = source.with_config(stdout=subprocess.PIPE, stderr=subprocess.STDOUT) \ + head_fetch = source.with_config(stdout=subprocess.PIPE, stderr=subprocess.STDOUT, check=False) \ .fetch(git.source_url(self.repository), root.head) - logger.info( - "Fetched head of %s (%s):\n%s", - root.display_name, - root.head, - tree.stdout.decode() - ) - if source.check(False).cat_file(e=root.head).returncode: + if head_fetch.returncode: raise ForwardPortError( f"During forward port of {self.display_name}, unable to find " f"expected head of {root.display_name} ({root.head})" ) + logger.info( + "Fetched head of %s (%s):\n%s", + root.display_name, + root.head, + head_fetch.stdout.decode() + ) + try: return None, root._cherry_pick(source, target_branch.name) except CherrypickError as e: diff --git a/forwardport/tests/test_conflicts.py b/forwardport/tests/test_conflicts.py index 7011b1b3..3c0bbda6 100644 --- a/forwardport/tests/test_conflicts.py +++ b/forwardport/tests/test_conflicts.py @@ -383,7 +383,6 @@ def test_multiple_commits_same_authorship(env, config, make_repo): assert get(c.committer) == get(committer) -@pytest.mark.expect_log_errors(reason="commits with incomplete authorship are unmergeable, which is logged as error") def test_multiple_commits_different_authorship(env, config, make_repo, users, rolemap): """ When a PR has multiple commits by different authors, the resulting (squashed) conflict commit should have an empty email diff --git a/forwardport/tests/test_limit.py b/forwardport/tests/test_limit.py index 1e8fcf7b..de563e3d 100644 --- a/forwardport/tests/test_limit.py +++ b/forwardport/tests/test_limit.py @@ -76,7 +76,6 @@ def test_ignore(env, config, make_repo, users): (users['user'], "Disabled forward-porting."), ] -@pytest.mark.expect_log_errors(reason="one of the limit-setting does not provide a branch name") def test_disable(env, config, make_repo, users): """ Checks behaviour if the limit target is disabled: diff --git a/runbot_merge/github.py b/runbot_merge/github.py index 2abcc495..98d2e4a3 100644 --- a/runbot_merge/github.py +++ b/runbot_merge/github.py @@ -253,7 +253,7 @@ class GH(object): raise exceptions.FastForwardError(self._repo) \ from Exception("timeout: never saw %s" % sha) except requests.HTTPError as e: - _logger.debug('fast_forward(%s, %s, %s) -> ERROR', self._repo, branch, sha, exc_info=True) + _logger.debug('fast_forward(%s, %s, %s) -> %s', self._repo, branch, sha, e) if e.response.status_code == 422: try: r = e.response.json() diff --git a/runbot_merge/models/pull_requests.py b/runbot_merge/models/pull_requests.py index c964c90d..a5870cdc 100644 --- a/runbot_merge/models/pull_requests.py +++ b/runbot_merge/models/pull_requests.py @@ -734,7 +734,6 @@ class PullRequests(models.Model): e, login, name, utils.shorten(comment['body'] or '', 50), - exc_info=True ) feedback(message=f"""@{login} {e.args[0]}. @@ -2284,9 +2283,9 @@ class Stagings(models.Model): self._safety_dance(gh, self.commits) except exceptions.FastForwardError as e: logger.warning( - "Could not fast-forward successful staging on %s:%s", + "Could not fast-forward successful staging on %s:%s: %s", e.args[0], self.target.name, - exc_info=True + e, ) self.write({ 'state': 'ff_failed', diff --git a/runbot_merge/models/stagings_create.py b/runbot_merge/models/stagings_create.py index 2005416b..55955a0a 100644 --- a/runbot_merge/models/stagings_create.py +++ b/runbot_merge/models/stagings_create.py @@ -259,7 +259,8 @@ def stage_batches(branch: Branch, batches: Batch, staging_state: StagingState) - staged |= stage_batch(env, batch, staging_state) except exceptions.MergeError as e: pr = e.args[0] - _logger.info("Failed to stage %s into %s", pr.display_name, branch.name, exc_info=True) + _logger.info("Failed to stage %s into %s", pr.display_name, branch.name) + pr._message_log(body=f"Failed to stage into {branch.name}: {e}") if not staged or isinstance(e, exceptions.Unmergeable): if len(e.args) > 1 and e.args[1]: reason = e.args[1] @@ -338,7 +339,8 @@ def stage_batch(env: api.Environment, batch: Batch, staging: StagingState): list(format_for_difflib((n, v) for n, v, _ in e.args[1])), list(format_for_difflib((n, v) for n, _, v in e.args[1])), )) - _logger.info("data mismatch on %s:\n%s", pr.display_name, diff) + _logger.info("Failed to stage %s: data mismatch", pr.display_name) + pr._message_log(body=f"data mismatch before merge:\n{diff}") env.ref('runbot_merge.pr.staging.mismatch')._send( repository=pr.repository, pull_request=pr.number, diff --git a/runbot_merge/tests/test_basic.py b/runbot_merge/tests/test_basic.py index c4be7fc5..abb03ec4 100644 --- a/runbot_merge/tests/test_basic.py +++ b/runbot_merge/tests/test_basic.py @@ -492,7 +492,6 @@ def test_staging_concurrent(env, repo, config): assert pr2.staging_id -@pytest.mark.expect_log_errors(reason="staging merge conflicts are logged") def test_staging_conflict_first(env, repo, users, config, page): """ If the first batch of a staging triggers a conflict, the PR should be marked as in error @@ -524,7 +523,6 @@ def test_staging_conflict_first(env, repo, users, config, page): assert dangerbox[0].text.strip() == 'Unable to stage PR' -@pytest.mark.expect_log_errors(reason="merge conflicts are logged as errors") def test_staging_conflict_second(env, repo, users, config): """ If the non-first batch of a staging triggers a conflict, the PR should just be skipped: it might be a conflict with an other PR which could fail @@ -648,7 +646,6 @@ def test_staging_ci_failure_single(env, repo, users, config, page): assert dangerbox[0].text == 'ci/runbot' -@pytest.mark.expect_log_errors(reason="failed fast forward of staging is a logged error") def test_ff_failure(env, repo, config, page): """ target updated while the PR is being staged => redo staging """ with repo: @@ -695,7 +692,6 @@ def test_ff_failure(env, repo, config, page): "PR should be staged to a new commit" -@pytest.mark.expect_log_errors(reason="blocking fast-forward of staging which triggers a logged error when trying to patch the GH ref") def test_ff_failure_batch(env, repo, users, config): with repo: m = repo.make_commit(None, 'initial', None, tree={'m': 'm'}) @@ -3615,7 +3611,6 @@ class TestRecognizeCommands: prx.post_comment('%shansen r+' % indent, config['role_reviewer']['token']) assert pr.state == 'approved' - @pytest.mark.expect_log_errors(reason="unknown commands are logged") def test_unknown_commands(self, repo, env, config, users): with repo: m = repo.make_commit(None, 'initial', None, tree={'m': 'm'}) diff --git a/runbot_merge/tests/test_multirepo.py b/runbot_merge/tests/test_multirepo.py index 35a6bcbc..3ac35a8f 100644 --- a/runbot_merge/tests/test_multirepo.py +++ b/runbot_merge/tests/test_multirepo.py @@ -397,7 +397,6 @@ def test_sub_match(env, project, repo_a, repo_b, repo_c, config): assert s == list(st.ids) -@pytest.mark.expect_log_errors(reason="merge errors are logged as errors") def test_merge_fail(env, project, repo_a, repo_b, users, config): """ In a matched-branch scenario, if merging in one of the linked repos fails it should revert the corresponding merges diff --git a/runbot_merge/tests/test_oddities.py b/runbot_merge/tests/test_oddities.py index 1454165b..6bee3696 100644 --- a/runbot_merge/tests/test_oddities.py +++ b/runbot_merge/tests/test_oddities.py @@ -173,7 +173,6 @@ def test_merge_empty_commits(env, repo, users, config): assert commits[2]['commit']['message'] == 'initial' -@pytest.mark.expect_log_errors(reason="emptied commits are merge errors and logged") def test_merge_emptying_commits(env, repo, users, config): """The mergebot should *not* allow merging non-empty commits which become empty as part of the staging (rebasing)