From de8772a655e49fc57138d91e6bb184dadeac838a Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Tue, 27 Nov 2018 03:00:33 +0100 Subject: Do a GC after each test to fix logcontext leaks (#4227) * Some words about garbage collections and logcontexts * Do a GC after each test to fix logcontext leaks This feels like an awful hack, but... * changelog --- tests/unittest.py | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-) (limited to 'tests/unittest.py') diff --git a/tests/unittest.py b/tests/unittest.py index a9ce57da9a..2049187fd9 100644 --- a/tests/unittest.py +++ b/tests/unittest.py @@ -13,7 +13,7 @@ # 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. - +import gc import hashlib import hmac import logging @@ -31,7 +31,7 @@ from synapse.http.server import JsonResource from synapse.http.site import SynapseRequest from synapse.server import HomeServer from synapse.types import UserID, create_requester -from synapse.util.logcontext import LoggingContextFilter +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 @@ -115,6 +115,17 @@ class TestCase(unittest.TestCase): logging.getLogger().setLevel(level) return orig() + @around(self) + def tearDown(orig): + ret = orig() + + # force a GC to workaround problems with deferreds leaking logcontexts when + # they are GCed (see the logcontext docs) + gc.collect() + LoggingContext.set_current_context(LoggingContext.sentinel) + + return ret + def assertObjectHasAttributes(self, attrs, obj): """Asserts that the given object has each of the attributes given, and that the value of each matches according to assertEquals.""" -- cgit 1.5.1 From a44c0a096fbdca979cb47a3e7308cfe52be8d684 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Tue, 27 Nov 2018 03:47:18 +0100 Subject: Check logcontexts before and after each test (#4190) * Add better diagnostics to flakey keyring test * fix interpolation fail * Check logcontexts before and after each test * update changelog * update changelog --- changelog.d/4190.misc | 1 + tests/crypto/test_keyring.py | 18 ++++++++++++------ tests/unittest.py | 11 +++++++++-- 3 files changed, 22 insertions(+), 8 deletions(-) create mode 100644 changelog.d/4190.misc (limited to 'tests/unittest.py') diff --git a/changelog.d/4190.misc b/changelog.d/4190.misc new file mode 100644 index 0000000000..6700a5150d --- /dev/null +++ b/changelog.d/4190.misc @@ -0,0 +1 @@ +Add some diagnostics to the tests to detect logcontext problems diff --git a/tests/crypto/test_keyring.py b/tests/crypto/test_keyring.py index 8299dc72c8..d643bec887 100644 --- a/tests/crypto/test_keyring.py +++ b/tests/crypto/test_keyring.py @@ -63,6 +63,14 @@ class KeyringTestCase(unittest.TestCase): keys = self.mock_perspective_server.get_verify_keys() self.hs.config.perspectives = {self.mock_perspective_server.server_name: keys} + def assert_sentinel_context(self): + if LoggingContext.current_context() != LoggingContext.sentinel: + self.fail( + "Expected sentinel context but got %s" % ( + LoggingContext.current_context(), + ) + ) + def check_context(self, _, expected): self.assertEquals( getattr(LoggingContext.current_context(), "request", None), expected @@ -70,8 +78,6 @@ class KeyringTestCase(unittest.TestCase): @defer.inlineCallbacks def test_wait_for_previous_lookups(self): - sentinel_context = LoggingContext.current_context() - kr = keyring.Keyring(self.hs) lookup_1_deferred = defer.Deferred() @@ -99,8 +105,10 @@ class KeyringTestCase(unittest.TestCase): ["server1"], {"server1": lookup_2_deferred} ) self.assertFalse(wait_2_deferred.called) + # ... so we should have reset the LoggingContext. - self.assertIs(LoggingContext.current_context(), sentinel_context) + self.assert_sentinel_context() + wait_2_deferred.addBoth(self.check_context, "two") # let the first lookup complete (in the sentinel context) @@ -198,8 +206,6 @@ class KeyringTestCase(unittest.TestCase): json1 = {} signedjson.sign.sign_json(json1, "server9", key1) - sentinel_context = LoggingContext.current_context() - with LoggingContext("one") as context_one: context_one.request = "one" @@ -213,7 +219,7 @@ class KeyringTestCase(unittest.TestCase): defer = kr.verify_json_for_server("server9", json1) self.assertFalse(defer.called) - self.assertIs(LoggingContext.current_context(), sentinel_context) + self.assert_sentinel_context() yield defer self.assertIs(LoggingContext.current_context(), context_one) diff --git a/tests/unittest.py b/tests/unittest.py index 2049187fd9..a191cccc29 100644 --- a/tests/unittest.py +++ b/tests/unittest.py @@ -102,8 +102,16 @@ class TestCase(unittest.TestCase): # traceback when a unit test exits leaving things on the reactor. twisted.internet.base.DelayedCall.debug = True - old_level = logging.getLogger().level + # if we're not starting in the sentinel logcontext, then to be honest + # all future bets are off. + if LoggingContext.current_context() is not LoggingContext.sentinel: + self.fail( + "Test starting with non-sentinel logging context %s" % ( + LoggingContext.current_context(), + ) + ) + old_level = logging.getLogger().level if old_level != level: @around(self) @@ -118,7 +126,6 @@ class TestCase(unittest.TestCase): @around(self) def tearDown(orig): ret = orig() - # force a GC to workaround problems with deferreds leaking logcontexts when # they are GCed (see the logcontext docs) gc.collect() -- cgit 1.5.1 From 48972ce9d10c67b49a0f7b4f45aa91551de0c830 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Tue, 4 Dec 2018 11:30:32 +0100 Subject: Patch defer.inlineCallbacks to check logcontexts in tests (#4205) --- changelog.d/4205.misc | 1 + tests/__init__.py | 7 +++- tests/patch_inline_callbacks.py | 90 +++++++++++++++++++++++++++++++++++++++++ tests/unittest.py | 4 +- 4 files changed, 99 insertions(+), 3 deletions(-) create mode 100644 changelog.d/4205.misc create mode 100644 tests/patch_inline_callbacks.py (limited to 'tests/unittest.py') 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() -- cgit 1.5.1