Merge branch 'develop' of github.com:matrix-org/synapse into erikj/admin_exfiltrate_data

6 files changed, 161 insertions, 58 deletions

diff --git a/tests/util/caches/test_descriptors.py b/tests/util/caches/test_descriptors.py
index 6f8f52537c..7807328e2f 100644
--- a/tests/util/caches/test_descriptors.py
+++ b/tests/util/caches/test_descriptors.py
@@ -21,7 +21,11 @@ import mock
 from twisted.internet import defer, reactor
 
 from synapse.api.errors import SynapseError
-from synapse.util import logcontext
+from synapse.logging.context import (
+    LoggingContext,
+    PreserveLoggingContext,
+    make_deferred_yieldable,
+)
 from synapse.util.caches import descriptors
 
 from tests import unittest
@@ -32,7 +36,7 @@ logger = logging.getLogger(__name__)
 def run_on_reactor():
     d = defer.Deferred()
     reactor.callLater(0, d.callback, 0)
-    return logcontext.make_deferred_yieldable(d)
+    return make_deferred_yieldable(d)
 
 
 class CacheTestCase(unittest.TestCase):
@@ -153,7 +157,7 @@ class DescriptorTestCase(unittest.TestCase):
             def fn(self, arg1):
                 @defer.inlineCallbacks
                 def inner_fn():
-                    with logcontext.PreserveLoggingContext():
+                    with PreserveLoggingContext():
                         yield complete_lookup
                     defer.returnValue(1)
 
@@ -161,10 +165,10 @@ class DescriptorTestCase(unittest.TestCase):
 
         @defer.inlineCallbacks
         def do_lookup():
-            with logcontext.LoggingContext() as c1:
+            with LoggingContext() as c1:
                 c1.name = "c1"
                 r = yield obj.fn(1)
-                self.assertEqual(logcontext.LoggingContext.current_context(), c1)
+                self.assertEqual(LoggingContext.current_context(), c1)
             defer.returnValue(r)
 
         def check_result(r):
@@ -174,18 +178,12 @@ class DescriptorTestCase(unittest.TestCase):
 
         # set off a deferred which will do a cache lookup
         d1 = do_lookup()
-        self.assertEqual(
-            logcontext.LoggingContext.current_context(),
-            logcontext.LoggingContext.sentinel,
-        )
+        self.assertEqual(LoggingContext.current_context(), LoggingContext.sentinel)
         d1.addCallback(check_result)
 
         # and another
         d2 = do_lookup()
-        self.assertEqual(
-            logcontext.LoggingContext.current_context(),
-            logcontext.LoggingContext.sentinel,
-        )
+        self.assertEqual(LoggingContext.current_context(), LoggingContext.sentinel)
         d2.addCallback(check_result)
 
         # let the lookup complete
@@ -210,29 +208,25 @@ class DescriptorTestCase(unittest.TestCase):
 
         @defer.inlineCallbacks
         def do_lookup():
-            with logcontext.LoggingContext() as c1:
+            with LoggingContext() as c1:
                 c1.name = "c1"
                 try:
                     d = obj.fn(1)
                     self.assertEqual(
-                        logcontext.LoggingContext.current_context(),
-                        logcontext.LoggingContext.sentinel,
+                        LoggingContext.current_context(), LoggingContext.sentinel
                     )
                     yield d
                     self.fail("No exception thrown")
                 except SynapseError:
                     pass
 
-                self.assertEqual(logcontext.LoggingContext.current_context(), c1)
+                self.assertEqual(LoggingContext.current_context(), c1)
 
         obj = Cls()
 
         # set off a deferred which will do a cache lookup
         d1 = do_lookup()
-        self.assertEqual(
-            logcontext.LoggingContext.current_context(),
-            logcontext.LoggingContext.sentinel,
-        )
+        self.assertEqual(LoggingContext.current_context(), LoggingContext.sentinel)
 
         return d1
 
@@ -288,23 +282,20 @@ class CachedListDescriptorTestCase(unittest.TestCase):
 
             @descriptors.cachedList("fn", "args1", inlineCallbacks=True)
             def list_fn(self, args1, arg2):
-                assert logcontext.LoggingContext.current_context().request == "c1"
+                assert LoggingContext.current_context().request == "c1"
                 # we want this to behave like an asynchronous function
                 yield run_on_reactor()
-                assert logcontext.LoggingContext.current_context().request == "c1"
+                assert LoggingContext.current_context().request == "c1"
                 defer.returnValue(self.mock(args1, arg2))
 
-        with logcontext.LoggingContext() as c1:
+        with LoggingContext() as c1:
             c1.request = "c1"
             obj = Cls()
             obj.mock.return_value = {10: "fish", 20: "chips"}
             d1 = obj.list_fn([10, 20], 2)
-            self.assertEqual(
-                logcontext.LoggingContext.current_context(),
-                logcontext.LoggingContext.sentinel,
-            )
+            self.assertEqual(LoggingContext.current_context(), LoggingContext.sentinel)
             r = yield d1
-            self.assertEqual(logcontext.LoggingContext.current_context(), c1)
+            self.assertEqual(LoggingContext.current_context(), c1)
             obj.mock.assert_called_once_with([10, 20], 2)
             self.assertEqual(r, {10: "fish", 20: "chips"})
             obj.mock.reset_mock()
diff --git a/tests/util/test_async_utils.py b/tests/util/test_async_utils.py
index bf85d3b8ec..f60918069a 100644
--- a/tests/util/test_async_utils.py
+++ b/tests/util/test_async_utils.py
@@ -16,9 +16,8 @@ from twisted.internet import defer
 from twisted.internet.defer import CancelledError, Deferred
 from twisted.internet.task import Clock
 
-from synapse.util import logcontext
+from synapse.logging.context import LoggingContext, PreserveLoggingContext
 from synapse.util.async_helpers import timeout_deferred
-from synapse.util.logcontext import LoggingContext
 
 from tests.unittest import TestCase
 
@@ -69,14 +68,14 @@ class TimeoutDeferredTest(TestCase):
         @defer.inlineCallbacks
         def blocking():
             non_completing_d = Deferred()
-            with logcontext.PreserveLoggingContext():
+            with PreserveLoggingContext():
                 try:
                     yield non_completing_d
                 except CancelledError:
                     blocking_was_cancelled[0] = True
                     raise
 
-        with logcontext.LoggingContext("one") as context_one:
+        with LoggingContext("one") as context_one:
             # the errbacks should be run in the test logcontext
             def errback(res, deferred_name):
                 self.assertIs(
diff --git a/tests/util/test_linearizer.py b/tests/util/test_linearizer.py
index ec7ba9719c..0ec8ef90ce 100644
--- a/tests/util/test_linearizer.py
+++ b/tests/util/test_linearizer.py
@@ -19,7 +19,8 @@ from six.moves import range
 from twisted.internet import defer, reactor
 from twisted.internet.defer import CancelledError
 
-from synapse.util import Clock, logcontext
+from synapse.logging.context import LoggingContext
+from synapse.util import Clock
 from synapse.util.async_helpers import Linearizer
 
 from tests import unittest
@@ -51,13 +52,13 @@ class LinearizerTestCase(unittest.TestCase):
 
         @defer.inlineCallbacks
         def func(i, sleep=False):
-            with logcontext.LoggingContext("func(%s)" % i) as lc:
+            with LoggingContext("func(%s)" % i) as lc:
                 with (yield linearizer.queue("")):
-                    self.assertEqual(logcontext.LoggingContext.current_context(), lc)
+                    self.assertEqual(LoggingContext.current_context(), lc)
                     if sleep:
                         yield Clock(reactor).sleep(0)
 
-                self.assertEqual(logcontext.LoggingContext.current_context(), lc)
+                self.assertEqual(LoggingContext.current_context(), lc)
 
         func(0, sleep=True)
         for i in range(1, 100):
diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py
index 8adaee3c8d..8b8455c8b7 100644
--- a/tests/util/test_logcontext.py
+++ b/tests/util/test_logcontext.py
@@ -1,8 +1,14 @@
 import twisted.python.failure
 from twisted.internet import defer, reactor
 
-from synapse.util import Clock, logcontext
-from synapse.util.logcontext import LoggingContext
+from synapse.logging.context import (
+    LoggingContext,
+    PreserveLoggingContext,
+    make_deferred_yieldable,
+    nested_logging_context,
+    run_in_background,
+)
+from synapse.util import Clock
 
 from .. import unittest
 
@@ -39,24 +45,17 @@ class LoggingContextTestCase(unittest.TestCase):
 
         callback_completed = [False]
 
-        def test():
+        with LoggingContext() as context_one:
             context_one.request = "one"
-            d = function()
+
+            # fire off function, but don't wait on it.
+            d2 = run_in_background(function)
 
             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.run_in_background(test)
+            d2.addCallback(cb)
 
             self._check_test_key("one")
 
@@ -92,7 +91,7 @@ class LoggingContextTestCase(unittest.TestCase):
     def test_run_in_background_with_non_blocking_fn(self):
         @defer.inlineCallbacks
         def nonblocking_function():
-            with logcontext.PreserveLoggingContext():
+            with PreserveLoggingContext():
                 yield defer.succeed(None)
 
         return self._test_run_in_background(nonblocking_function)
@@ -101,7 +100,23 @@ class LoggingContextTestCase(unittest.TestCase):
         # 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 make_deferred_yieldable(_chained_deferred_function())
+
+        return self._test_run_in_background(testfunc)
+
+    def test_run_in_background_with_coroutine(self):
+        async def testfunc():
+            self._check_test_key("one")
+            d = Clock(reactor).sleep(0)
+            self.assertIs(LoggingContext.current_context(), LoggingContext.sentinel)
+            await d
+            self._check_test_key("one")
+
+        return self._test_run_in_background(testfunc)
+
+    def test_run_in_background_with_nonblocking_coroutine(self):
+        async def testfunc():
+            self._check_test_key("one")
 
         return self._test_run_in_background(testfunc)
 
@@ -119,7 +134,7 @@ class LoggingContextTestCase(unittest.TestCase):
         with LoggingContext() as context_one:
             context_one.request = "one"
 
-            d1 = logcontext.make_deferred_yieldable(blocking_function())
+            d1 = make_deferred_yieldable(blocking_function())
             # make sure that the context was reset by make_deferred_yieldable
             self.assertIs(LoggingContext.current_context(), sentinel_context)
 
@@ -135,7 +150,7 @@ class LoggingContextTestCase(unittest.TestCase):
         with LoggingContext() as context_one:
             context_one.request = "one"
 
-            d1 = logcontext.make_deferred_yieldable(_chained_deferred_function())
+            d1 = make_deferred_yieldable(_chained_deferred_function())
             # make sure that the context was reset by make_deferred_yieldable
             self.assertIs(LoggingContext.current_context(), sentinel_context)
 
@@ -152,7 +167,7 @@ class LoggingContextTestCase(unittest.TestCase):
         with LoggingContext() as context_one:
             context_one.request = "one"
 
-            d1 = logcontext.make_deferred_yieldable("bum")
+            d1 = make_deferred_yieldable("bum")
             self._check_test_key("one")
 
             r = yield d1
@@ -161,7 +176,7 @@ class LoggingContextTestCase(unittest.TestCase):
 
     def test_nested_logging_context(self):
         with LoggingContext(request="foo"):
-            nested_context = logcontext.nested_logging_context(suffix="bar")
+            nested_context = nested_logging_context(suffix="bar")
             self.assertEqual(nested_context.request, "foo-bar")
 
 
diff --git a/tests/util/test_logformatter.py b/tests/util/test_logformatter.py
index 297aebbfbe..0fb60caacb 100644
--- a/tests/util/test_logformatter.py
+++ b/tests/util/test_logformatter.py
@@ -14,7 +14,7 @@
 # limitations under the License.
 import sys
 
-from synapse.util.logformatter import LogFormatter
+from synapse.logging.formatter import LogFormatter
 
 from tests import unittest
 
diff --git a/tests/util/test_ratelimitutils.py b/tests/util/test_ratelimitutils.py
new file mode 100644
index 0000000000..4d1aee91d5
--- /dev/null
+++ b/tests/util/test_ratelimitutils.py
@@ -0,0 +1,97 @@
+# -*- coding: utf-8 -*-
+# Copyright 2019 The Matrix.org Foundation C.I.C.
+#
+# 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 synapse.config.homeserver import HomeServerConfig
+from synapse.util.ratelimitutils import FederationRateLimiter
+
+from tests.server import get_clock
+from tests.unittest import TestCase
+from tests.utils import default_config
+
+
+class FederationRateLimiterTestCase(TestCase):
+    def test_ratelimit(self):
+        """A simple test with the default values"""
+        reactor, clock = get_clock()
+        rc_config = build_rc_config()
+        ratelimiter = FederationRateLimiter(clock, rc_config)
+
+        with ratelimiter.ratelimit("testhost") as d1:
+            # shouldn't block
+            self.successResultOf(d1)
+
+    def test_concurrent_limit(self):
+        """Test what happens when we hit the concurrent limit"""
+        reactor, clock = get_clock()
+        rc_config = build_rc_config({"rc_federation": {"concurrent": 2}})
+        ratelimiter = FederationRateLimiter(clock, rc_config)
+
+        with ratelimiter.ratelimit("testhost") as d1:
+            # shouldn't block
+            self.successResultOf(d1)
+
+            cm2 = ratelimiter.ratelimit("testhost")
+            d2 = cm2.__enter__()
+            # also shouldn't block
+            self.successResultOf(d2)
+
+            cm3 = ratelimiter.ratelimit("testhost")
+            d3 = cm3.__enter__()
+            # this one should block, though ...
+            self.assertNoResult(d3)
+
+            # ... until we complete an earlier request
+            cm2.__exit__(None, None, None)
+            self.successResultOf(d3)
+
+    def test_sleep_limit(self):
+        """Test what happens when we hit the sleep limit"""
+        reactor, clock = get_clock()
+        rc_config = build_rc_config(
+            {"rc_federation": {"sleep_limit": 2, "sleep_delay": 500}}
+        )
+        ratelimiter = FederationRateLimiter(clock, rc_config)
+
+        with ratelimiter.ratelimit("testhost") as d1:
+            # shouldn't block
+            self.successResultOf(d1)
+
+        with ratelimiter.ratelimit("testhost") as d2:
+            # nor this
+            self.successResultOf(d2)
+
+        with ratelimiter.ratelimit("testhost") as d3:
+            # this one should block, though ...
+            self.assertNoResult(d3)
+            sleep_time = _await_resolution(reactor, d3)
+            self.assertAlmostEqual(sleep_time, 500, places=3)
+
+
+def _await_resolution(reactor, d):
+    """advance the clock until the deferred completes.
+
+    Returns the number of milliseconds it took to complete.
+    """
+    start_time = reactor.seconds()
+    while not d.called:
+        reactor.advance(0.01)
+    return (reactor.seconds() - start_time) * 1000
+
+
+def build_rc_config(settings={}):
+    config_dict = default_config("test")
+    config_dict.update(settings)
+    config = HomeServerConfig()
+    config.parse_config_dict(config_dict, "", "")
+    return config.rc_federation