[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

@@ -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:

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

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:
 

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()

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',

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,

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'})

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

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)