Patch defer.inlineCallbacks to check logcontexts in tests (#4205)

4 files changed, 99 insertions, 3 deletions

diff --git a/changelog.d/4205.misc b/changelog.d/4205.misc
new file mode 100644
index 0000000000..bbdce2c7aa
--- /dev/null
+++ b/changelog.d/4205.misc
@@ -0,0 +1 @@
+More logcontext checking in unittests
diff --git a/tests/__init__.py b/tests/__init__.py
index 9d9ca22829..d3181f9403 100644
--- a/tests/__init__.py
+++ b/tests/__init__.py
@@ -1,5 +1,6 @@
 # -*- coding: utf-8 -*-
 # Copyright 2014-2016 OpenMarket Ltd
+# Copyright 2018 New Vector Ltd
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
 # you may not use this file except in compliance with the License.
@@ -15,7 +16,9 @@
 
 from twisted.trial import util
 
-from tests import utils
+import tests.patch_inline_callbacks
+
+# attempt to do the patch before we load any synapse code
+tests.patch_inline_callbacks.do_patch()
 
 util.DEFAULT_TIMEOUT_DURATION = 10
-utils.setupdb()
diff --git a/tests/patch_inline_callbacks.py b/tests/patch_inline_callbacks.py
new file mode 100644
index 0000000000..0f613945c8
--- /dev/null
+++ b/tests/patch_inline_callbacks.py
@@ -0,0 +1,90 @@
+# -*- coding: utf-8 -*-
+# Copyright 2018 New Vector Ltd
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+from __future__ import print_function
+
+import functools
+import sys
+
+from twisted.internet import defer
+from twisted.internet.defer import Deferred
+from twisted.python.failure import Failure
+
+
+def do_patch():
+    """
+    Patch defer.inlineCallbacks so that it checks the state of the logcontext on exit
+    """
+
+    from synapse.util.logcontext import LoggingContext
+
+    orig_inline_callbacks = defer.inlineCallbacks
+
+    def new_inline_callbacks(f):
+
+        orig = orig_inline_callbacks(f)
+
+        @functools.wraps(f)
+        def wrapped(*args, **kwargs):
+            start_context = LoggingContext.current_context()
+
+            try:
+                res = orig(*args, **kwargs)
+            except Exception:
+                if LoggingContext.current_context() != start_context:
+                    err = "%s changed context from %s to %s on exception" % (
+                        f, start_context, LoggingContext.current_context()
+                    )
+                    print(err, file=sys.stderr)
+                    raise Exception(err)
+                raise
+
+            if not isinstance(res, Deferred) or res.called:
+                if LoggingContext.current_context() != start_context:
+                    err = "%s changed context from %s to %s" % (
+                        f, start_context, LoggingContext.current_context()
+                    )
+                    # print the error to stderr because otherwise all we
+                    # see in travis-ci is the 500 error
+                    print(err, file=sys.stderr)
+                    raise Exception(err)
+                return res
+
+            if LoggingContext.current_context() != LoggingContext.sentinel:
+                err = (
+                    "%s returned incomplete deferred in non-sentinel context "
+                    "%s (start was %s)"
+                ) % (
+                    f, LoggingContext.current_context(), start_context,
+                )
+                print(err, file=sys.stderr)
+                raise Exception(err)
+
+            def check_ctx(r):
+                if LoggingContext.current_context() != start_context:
+                    err = "%s completion of %s changed context from %s to %s" % (
+                        "Failure" if isinstance(r, Failure) else "Success",
+                        f, start_context, LoggingContext.current_context(),
+                    )
+                    print(err, file=sys.stderr)
+                    raise Exception(err)
+                return r
+
+            res.addBoth(check_ctx)
+            return res
+
+        return wrapped
+
+    defer.inlineCallbacks = new_inline_callbacks
diff --git a/tests/unittest.py b/tests/unittest.py
index a191cccc29..092c930396 100644
--- a/tests/unittest.py
+++ b/tests/unittest.py
@@ -34,7 +34,9 @@ from synapse.types import UserID, create_requester
 from synapse.util.logcontext import LoggingContext, LoggingContextFilter
 
 from tests.server import get_clock, make_request, render, setup_test_homeserver
-from tests.utils import default_config
+from tests.utils import default_config, setupdb
+
+setupdb()
 
 # Set up putting Synapse's logs into Trial's.
 rootLogger = logging.getLogger()