[IMP] *: require explicitly specifying whether exceptions in logs are valid

Seems like a good idea to better keep track of the log of an Odoo used
to testing, and avoid silently ignoring logged errors.

- intercept odoo's stderr via a pipe, that way we can still write it
  back out and pytest is able to read & buffer it, pytest's capfd
  would not work correctly: it breaks output capturing (and printing
  on failure); and because of the way it hooks in it's unable to
  capture from subprocesses inheriting the standard stream, cf
  pytest-dev/pytest#4428
- update the env fixture to check that the odoo log doesn't have any
  exception on failure
- make that check conditional on the `expect_log_errors` marker, this
  way we can mark tests for which we expect errors to be logged, and
  assert that that does happen

conftest.py

@@ -1,5 +1,7 @@
 from __future__ import annotations
 
+import select
+import threading
 from typing import Optional
 
 """
@@ -94,9 +96,12 @@ def pytest_addoption(parser):
 def is_manager(config):
     return not hasattr(config, 'workerinput')
 
-# noinspection PyUnusedLocal
 def pytest_configure(config):
     sys.path.insert(0, os.path.join(os.path.dirname(__file__), 'mergebot_test_utils'))
+    config.addinivalue_line(
+        "markers",
+        "expect_log_errors(reason): allow and require tracebacks in the log",
+    )
 
 def pytest_unconfigure(config):
     if not is_manager(config):
@@ -418,6 +423,19 @@ def server(request, db, port, module, addons_path, tmpdir):
     if request.config.getoption('--coverage'):
         cov = ['coverage', 'run', '-p', '--source=odoo.addons.runbot_merge,odoo.addons.forwardport', '--branch']
 
+    r, w = os.pipe2(os.O_NONBLOCK)
+    buf = bytearray()
+    def _move(inpt=r, output=sys.stdout.fileno()):
+        while p.poll() is None:
+            readable, _, _ = select.select([inpt], [], [], 1)
+            if readable:
+                r = os.read(inpt, 4096)
+                if not r:
+                    break
+                os.write(output, r)
+                buf.extend(r)
+        os.close(inpt)
+
     p = subprocess.Popen([
         *cov,
         'odoo', '--http-port', str(port),
@@ -425,25 +443,35 @@ def server(request, db, port, module, addons_path, tmpdir):
         '-d', db,
         '--max-cron-threads', '0', # disable cron threads (we're running crons by hand)
         *itertools.chain.from_iterable(('--log-handler', h) for h in log_handlers),
-    ], env={
+    ], stderr=w, env={
         **os.environ,
         # stop putting garbage in the user dirs, and potentially creating conflicts
         # TODO: way to override this with macOS?
         'XDG_DATA_HOME': str(tmpdir.mkdir('share')),
         'XDG_CACHE_HOME': str(tmpdir.mkdir('cache')),
     })
+    os.close(w)
+    # start the reader thread here so `_move` can read `p` without needing
+    # additional handholding
+    threading.Thread(target=_move, daemon=True).start()
 
     try:
         wait_for_server(db, port, p, module)
 
-        yield p
+        yield p, buf
     finally:
         p.terminate()
         p.wait(timeout=30)
 
 @pytest.fixture
-def env(port, server, db, default_crons):
+def env(request, port, server, db, default_crons):
     yield Environment(port, db, default_crons)
+    if request.node.get_closest_marker('expect_log_errors'):
+        if b"Traceback (most recent call last):" not in server[1]:
+            pytest.fail("should have found error in logs.")
+    else:
+        if b"Traceback (most recent call last):" in server[1]:
+            pytest.fail("unexpected error in logs, fix, or mark function as `expect_log_errors` to require.")
 
 def check(response):
     assert response.ok, response.text or response.reason

forwardport/tests/test_conflicts.py

@@ -2,6 +2,8 @@ import re
 import time
 from operator import itemgetter
 
+import pytest
+
 from utils import make_basic, Commit, validate_all, matches, seen, REF_PATTERN, to_pr
 
 
@@ -296,6 +298,8 @@ def test_multiple_commits_same_authorship(env, config, make_repo):
     assert get(c.author) == get(author)
     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

@@ -56,6 +56,7 @@ def test_ignore(env, config, make_repo):
         "should not have created a forward port"
 
 
+@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:
 

forwardport/tests/test_weird.py

@@ -853,6 +853,8 @@ def test_freeze(env, config, make_repo, users):
     assert env['runbot_merge.pull_requests'].search_count([('state', '=', 'merged')]) \
         == len(['release', 'initial', 'fw-b', 'fw-post-b', 'fw-c'])
 
+
+@pytest.mark.expect_log_errors(reason="missing / invalid head causes an error to be logged")
 def test_missing_magic_ref(env, config, make_repo):
     """There are cases where github fails to create / publish or fails to update
     the magic refs in refs/pull/*.

runbot_merge/tests/test_basic.py

@@ -482,6 +482,8 @@ 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
@@ -512,6 +514,8 @@ def test_staging_conflict_first(env, repo, users, config, page):
     assert dangerbox
     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
@@ -634,6 +638,8 @@ def test_staging_ci_failure_single(env, repo, users, config, page):
     assert dangerbox
     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:
@@ -679,6 +685,8 @@ def test_ff_failure(env, repo, config, page):
     assert repo.commit('heads/staging.master').id != staging.id,\
         "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'})
@@ -3619,6 +3627,7 @@ 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

@@ -396,6 +396,8 @@ 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

@@ -1,3 +1,4 @@
+import pytest
 import requests
 
 from utils import Commit, to_pr
@@ -171,6 +172,8 @@ def test_merge_empty_commits(env, repo, users, config):
     assert commits[1]['commit']['message'].startswith('thing1')
     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)