Merge remote-tracking branch 'origin/develop' into rav/warn_on_logcontext_fail

5 files changed, 123 insertions, 27 deletions

diff --git a/tests/util/caches/test_descriptors.py b/tests/util/caches/test_descriptors.py
index 3f14ab503f..2516fe40f4 100644
--- a/tests/util/caches/test_descriptors.py
+++ b/tests/util/caches/test_descriptors.py
@@ -1,5 +1,6 @@
 # -*- coding: utf-8 -*-
 # Copyright 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.
@@ -12,6 +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.
+from functools import partial
 import logging
 
 import mock
@@ -25,6 +27,50 @@ from tests import unittest
 logger = logging.getLogger(__name__)
 
 
+class CacheTestCase(unittest.TestCase):
+    def test_invalidate_all(self):
+        cache = descriptors.Cache("testcache")
+
+        callback_record = [False, False]
+
+        def record_callback(idx):
+            callback_record[idx] = True
+
+        # add a couple of pending entries
+        d1 = defer.Deferred()
+        cache.set("key1", d1, partial(record_callback, 0))
+
+        d2 = defer.Deferred()
+        cache.set("key2", d2, partial(record_callback, 1))
+
+        # lookup should return the deferreds
+        self.assertIs(cache.get("key1"), d1)
+        self.assertIs(cache.get("key2"), d2)
+
+        # let one of the lookups complete
+        d2.callback("result2")
+        self.assertEqual(cache.get("key2"), "result2")
+
+        # now do the invalidation
+        cache.invalidate_all()
+
+        # lookup should return none
+        self.assertIsNone(cache.get("key1", None))
+        self.assertIsNone(cache.get("key2", None))
+
+        # both callbacks should have been callbacked
+        self.assertTrue(
+            callback_record[0], "Invalidation callback for key1 not called",
+        )
+        self.assertTrue(
+            callback_record[1], "Invalidation callback for key2 not called",
+        )
+
+        # letting the other lookup complete should do nothing
+        d1.callback("result1")
+        self.assertIsNone(cache.get("key1", None))
+
+
 class DescriptorTestCase(unittest.TestCase):
     @defer.inlineCallbacks
     def test_cache(self):
diff --git a/tests/util/test_file_consumer.py b/tests/util/test_file_consumer.py
index 76e2234255..d6e1082779 100644
--- a/tests/util/test_file_consumer.py
+++ b/tests/util/test_file_consumer.py
@@ -20,7 +20,7 @@ from mock import NonCallableMock
 from synapse.util.file_consumer import BackgroundFileConsumer
 
 from tests import unittest
-from StringIO import StringIO
+from six import StringIO
 
 import threading
 
diff --git a/tests/util/test_linearizer.py b/tests/util/test_linearizer.py
index 793a88e462..4865eb4bc6 100644
--- a/tests/util/test_linearizer.py
+++ b/tests/util/test_linearizer.py
@@ -18,6 +18,7 @@ from tests import unittest
 from twisted.internet import defer
 
 from synapse.util.async import Linearizer
+from six.moves import range
 
 
 class LinearizerTestCase(unittest.TestCase):
@@ -58,7 +59,7 @@ class LinearizerTestCase(unittest.TestCase):
                     logcontext.LoggingContext.current_context(), lc)
 
         func(0, sleep=True)
-        for i in xrange(1, 100):
+        for i in range(1, 100):
             func(i)
 
         return func(1000)
diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py
index 4850722bc5..ad78d884e0 100644
--- a/tests/util/test_logcontext.py
+++ b/tests/util/test_logcontext.py
@@ -36,24 +36,28 @@ class LoggingContextTestCase(unittest.TestCase):
             yield sleep(0)
             self._check_test_key("one")
 
-    def _test_preserve_fn(self, function):
+    def _test_run_in_background(self, function):
         sentinel_context = LoggingContext.current_context()
 
         callback_completed = [False]
 
-        @defer.inlineCallbacks
-        def cb():
+        def test():
             context_one.request = "one"
-            yield function()
-            self._check_test_key("one")
+            d = function()
 
-            callback_completed[0] = True
+            def cb(res):
+                self._check_test_key("one")
+                callback_completed[0] = True
+                return res
+            d.addCallback(cb)
+
+            return d
 
         with LoggingContext() as context_one:
             context_one.request = "one"
 
             # fire off function, but don't wait on it.
-            logcontext.preserve_fn(cb)()
+            logcontext.run_in_background(test)
 
             self._check_test_key("one")
 
@@ -80,20 +84,30 @@ class LoggingContextTestCase(unittest.TestCase):
         # test is done once d2 finishes
         return d2
 
-    def test_preserve_fn_with_blocking_fn(self):
+    def test_run_in_background_with_blocking_fn(self):
         @defer.inlineCallbacks
         def blocking_function():
             yield sleep(0)
 
-        return self._test_preserve_fn(blocking_function)
+        return self._test_run_in_background(blocking_function)
 
-    def test_preserve_fn_with_non_blocking_fn(self):
+    def test_run_in_background_with_non_blocking_fn(self):
         @defer.inlineCallbacks
         def nonblocking_function():
             with logcontext.PreserveLoggingContext():
                 yield defer.succeed(None)
 
-        return self._test_preserve_fn(nonblocking_function)
+        return self._test_run_in_background(nonblocking_function)
+
+    def test_run_in_background_with_chained_deferred(self):
+        # a function which returns a deferred which looks like it has been
+        # called, but is actually paused
+        def testfunc():
+            return logcontext.make_deferred_yieldable(
+                _chained_deferred_function()
+            )
+
+        return self._test_run_in_background(testfunc)
 
     @defer.inlineCallbacks
     def test_make_deferred_yieldable(self):
@@ -119,6 +133,22 @@ class LoggingContextTestCase(unittest.TestCase):
             self._check_test_key("one")
 
     @defer.inlineCallbacks
+    def test_make_deferred_yieldable_with_chained_deferreds(self):
+        sentinel_context = LoggingContext.current_context()
+
+        with LoggingContext() as context_one:
+            context_one.request = "one"
+
+            d1 = logcontext.make_deferred_yieldable(_chained_deferred_function())
+            # make sure that the context was reset by make_deferred_yieldable
+            self.assertIs(LoggingContext.current_context(), sentinel_context)
+
+            yield d1
+
+            # now it should be restored
+            self._check_test_key("one")
+
+    @defer.inlineCallbacks
     def test_make_deferred_yieldable_on_non_deferred(self):
         """Check that make_deferred_yieldable does the right thing when its
         argument isn't actually a deferred"""
@@ -132,3 +162,17 @@ class LoggingContextTestCase(unittest.TestCase):
             r = yield d1
             self.assertEqual(r, "bum")
             self._check_test_key("one")
+
+
+# a function which returns a deferred which has been "called", but
+# which had a function which returned another incomplete deferred on
+# its callback list, so won't yet call any other new callbacks.
+def _chained_deferred_function():
+    d = defer.succeed(None)
+
+    def cb(res):
+        d2 = defer.Deferred()
+        reactor.callLater(0, d2.callback, res)
+        return d2
+    d.addCallback(cb)
+    return d
diff --git a/tests/util/test_clock.py b/tests/util/test_logformatter.py
index 9672603579..1a1a8412f2 100644
--- a/tests/util/test_clock.py
+++ b/tests/util/test_logformatter.py
@@ -1,5 +1,5 @@
 # -*- coding: utf-8 -*-
-# Copyright 2017 Vector Creations 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.
@@ -12,22 +12,27 @@
 # 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 synapse import util
-from twisted.internet import defer
+import sys
+
+from synapse.util.logformatter import LogFormatter
 from tests import unittest
 
 
-class ClockTestCase(unittest.TestCase):
-    @defer.inlineCallbacks
-    def test_time_bound_deferred(self):
-        # just a deferred which never resolves
-        slow_deferred = defer.Deferred()
+class TestException(Exception):
+    pass
+
 
-        clock = util.Clock()
-        time_bound = clock.time_bound_deferred(slow_deferred, 0.001)
+class LogFormatterTestCase(unittest.TestCase):
+    def test_formatter(self):
+        formatter = LogFormatter()
 
         try:
-            yield time_bound
-            self.fail("Expected timedout error, but got nothing")
-        except util.DeferredTimedOutError:
-            pass
+            raise TestException("testytest")
+        except TestException:
+            ei = sys.exc_info()
+
+        output = formatter.formatException(ei)
+
+        # check the output looks vaguely sane
+        self.assertIn("testytest", output)
+        self.assertIn("Capture point", output)