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') 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 80527b568d64e402e91a85710e72d99448b4e384 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Tue, 27 Nov 2018 03:01:04 +0100 Subject: Fix more logcontext leaks in tests (#4209) --- changelog.d/4209.misc | 1 + tests/rest/media/v1/test_media_storage.py | 3 ++- 2 files changed, 3 insertions(+), 1 deletion(-) create mode 100644 changelog.d/4209.misc (limited to 'tests') diff --git a/changelog.d/4209.misc b/changelog.d/4209.misc new file mode 100644 index 0000000000..efd1f4abd6 --- /dev/null +++ b/changelog.d/4209.misc @@ -0,0 +1 @@ +Fix logcontext leaks in EmailPusher and in tests \ No newline at end of file diff --git a/tests/rest/media/v1/test_media_storage.py b/tests/rest/media/v1/test_media_storage.py index fd131e3454..ad5e9a612f 100644 --- a/tests/rest/media/v1/test_media_storage.py +++ b/tests/rest/media/v1/test_media_storage.py @@ -30,6 +30,7 @@ from synapse.rest.media.v1._base import FileInfo from synapse.rest.media.v1.filepath import MediaFilePaths from synapse.rest.media.v1.media_storage import MediaStorage from synapse.rest.media.v1.storage_provider import FileStorageProviderBackend +from synapse.util.logcontext import make_deferred_yieldable from synapse.util.module_loader import load_module from tests import unittest @@ -113,7 +114,7 @@ class MediaRepoTests(unittest.HomeserverTestCase): d = Deferred() d.addCallback(write_to) self.fetches.append((d, destination, path, args)) - return d + return make_deferred_yieldable(d) client = Mock() client.get_file = get_file -- 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') 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 7039ece8fb633b97cd6166be636bae71fb3aa3c6 Mon Sep 17 00:00:00 2001 From: Neil Johnson Date: Wed, 28 Nov 2018 11:24:57 +0000 Subject: Neilj/fix autojoin (#4223) * Fix auto join failures for servers that require user consent * Fix auto join failures for servers that require user consent --- changelog.d/4223.bugfix | 1 + synapse/handlers/register.py | 23 +++++++++++++++++++++-- synapse/rest/client/v2_alpha/register.py | 1 + synapse/rest/consent/consent_resource.py | 2 ++ tests/handlers/test_register.py | 12 +++++++++++- 5 files changed, 36 insertions(+), 3 deletions(-) create mode 100644 changelog.d/4223.bugfix (limited to 'tests') diff --git a/changelog.d/4223.bugfix b/changelog.d/4223.bugfix new file mode 100644 index 0000000000..bab591a765 --- /dev/null +++ b/changelog.d/4223.bugfix @@ -0,0 +1 @@ +Fix auto join failures for servers that require user consent diff --git a/synapse/handlers/register.py b/synapse/handlers/register.py index d2beb275cf..015909bb26 100644 --- a/synapse/handlers/register.py +++ b/synapse/handlers/register.py @@ -217,7 +217,19 @@ class RegistrationHandler(BaseHandler): user_id = None token = None attempts += 1 + if not self.hs.config.user_consent_at_registration: + yield self._auto_join_rooms(user_id) + defer.returnValue((user_id, token)) + + @defer.inlineCallbacks + def _auto_join_rooms(self, user_id): + """Automatically joins users to auto join rooms - creating the room in the first place + if the user is the first to be created. + + Args: + user_id(str): The user to join + """ # auto-join the user to any rooms we're supposed to dump them into fake_requester = create_requester(user_id) @@ -226,7 +238,6 @@ class RegistrationHandler(BaseHandler): if self.hs.config.autocreate_auto_join_rooms: count = yield self.store.count_all_users() should_auto_create_rooms = count == 1 - for r in self.hs.config.auto_join_rooms: try: if should_auto_create_rooms: @@ -256,7 +267,15 @@ class RegistrationHandler(BaseHandler): except Exception as e: logger.error("Failed to join new user to %r: %r", r, e) - defer.returnValue((user_id, token)) + @defer.inlineCallbacks + def post_consent_actions(self, user_id): + """A series of registration actions that can only be carried out once consent + has been granted + + Args: + user_id (str): The user to join + """ + yield self._auto_join_rooms(user_id) @defer.inlineCallbacks def appservice_register(self, user_localpart, as_token): diff --git a/synapse/rest/client/v2_alpha/register.py b/synapse/rest/client/v2_alpha/register.py index 0515715f7c..aec0c6b075 100644 --- a/synapse/rest/client/v2_alpha/register.py +++ b/synapse/rest/client/v2_alpha/register.py @@ -457,6 +457,7 @@ class RegisterRestServlet(RestServlet): yield self.store.user_set_consent_version( registered_user_id, self.hs.config.user_consent_version, ) + yield self.registration_handler.post_consent_actions(registered_user_id) defer.returnValue((200, return_dict)) diff --git a/synapse/rest/consent/consent_resource.py b/synapse/rest/consent/consent_resource.py index ad525b22e1..80611cfe84 100644 --- a/synapse/rest/consent/consent_resource.py +++ b/synapse/rest/consent/consent_resource.py @@ -89,6 +89,7 @@ class ConsentResource(Resource): self.hs = hs self.store = hs.get_datastore() + self.registration_handler = hs.get_handlers().registration_handler # this is required by the request_handler wrapper self.clock = hs.get_clock() @@ -199,6 +200,7 @@ class ConsentResource(Resource): if e.code != 404: raise raise NotFoundError("Unknown user") + yield self.registration_handler.post_consent_actions(qualified_user_id) try: self._render_template(request, "success.html") diff --git a/tests/handlers/test_register.py b/tests/handlers/test_register.py index 3e9a190727..90a2a76475 100644 --- a/tests/handlers/test_register.py +++ b/tests/handlers/test_register.py @@ -150,7 +150,6 @@ class RegistrationTestCase(unittest.TestCase): self.hs.config.auto_join_rooms = [room_alias_str] res = yield self.handler.register(localpart='jeff') rooms = yield self.store.get_rooms_for_user(res[0]) - directory_handler = self.hs.get_handlers().directory_handler room_alias = RoomAlias.from_string(room_alias_str) room_id = yield directory_handler.get_association(room_alias) @@ -184,3 +183,14 @@ class RegistrationTestCase(unittest.TestCase): res = yield self.handler.register(localpart='jeff') rooms = yield self.store.get_rooms_for_user(res[0]) self.assertEqual(len(rooms), 0) + + @defer.inlineCallbacks + def test_auto_create_auto_join_where_no_consent(self): + self.hs.config.user_consent_at_registration = True + self.hs.config.block_events_without_consent_error = "Error" + room_alias_str = "#room:test" + self.hs.config.auto_join_rooms = [room_alias_str] + res = yield self.handler.register(localpart='jeff') + yield self.handler.post_consent_actions(res[0]) + rooms = yield self.store.get_rooms_for_user(res[0]) + self.assertEqual(len(rooms), 0) -- 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') 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