diff --git a/changelog.d/4205.misc b/changelog.d/4205.misc new file mode 100644 index 000000000..bbdce2c7a --- /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 9d9ca2282..d3181f940 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 000000000..0f613945c --- /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 a191cccc2..092c93039 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()