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: [PATCH] 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 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()