Merge branch 'develop' of github.com:matrix-org/synapse into neilj/create_support_user

12 files changed, 145 insertions, 63 deletions

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/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/changelog.d/4220.feature b/changelog.d/4220.feature
new file mode 100644
index 0000000000..e7a3e40483
--- /dev/null
+++ b/changelog.d/4220.feature
@@ -0,0 +1 @@
+Rename login type m.login.cas to m.login.sso
diff --git a/changelog.d/4227.misc b/changelog.d/4227.misc
new file mode 100644
index 0000000000..7ebd51b6a4
--- /dev/null
+++ b/changelog.d/4227.misc
@@ -0,0 +1 @@
+Garbage-collect after each unit test to fix logcontext leaks
\ No newline at end of file
diff --git a/docs/log_contexts.rst b/docs/log_contexts.rst
index 82ac4f91e5..27cde11cf7 100644
--- a/docs/log_contexts.rst
+++ b/docs/log_contexts.rst
@@ -163,7 +163,7 @@ the logcontext was set, this will make things work out ok: provided
 It's all too easy to forget to ``yield``: for instance if we forgot that
 ``do_some_stuff`` returned a deferred, we might plough on regardless. This
 leads to a mess; it will probably work itself out eventually, but not before
-a load of stuff has been logged against the wrong content. (Normally, other
+a load of stuff has been logged against the wrong context. (Normally, other
 things will break, more obviously, if you forget to ``yield``, so this tends
 not to be a major problem in practice.)
 
@@ -440,3 +440,59 @@ To conclude: I think this scheme would have worked equally well, with less
 danger of messing it up, and probably made some more esoteric code easier to
 write. But again — changing the conventions of the entire Synapse codebase is
 not a sensible option for the marginal improvement offered.
+
+
+A note on garbage-collection of Deferred chains
+-----------------------------------------------
+
+It turns out that our logcontext rules do not play nicely with Deferred
+chains which get orphaned and garbage-collected.
+
+Imagine we have some code that looks like this:
+
+.. code:: python
+
+    listener_queue = []
+
+    def on_something_interesting():
+        for d in listener_queue:
+            d.callback("foo")
+
+    @defer.inlineCallbacks
+    def await_something_interesting():
+        new_deferred = defer.Deferred()
+        listener_queue.append(new_deferred)
+
+        with PreserveLoggingContext():
+            yield new_deferred
+
+Obviously, the idea here is that we have a bunch of things which are waiting
+for an event. (It's just an example of the problem here, but a relatively
+common one.)
+
+Now let's imagine two further things happen. First of all, whatever was
+waiting for the interesting thing goes away. (Perhaps the request times out,
+or something *even more* interesting happens.)
+
+Secondly, let's suppose that we decide that the interesting thing is never
+going to happen, and we reset the listener queue:
+
+.. code:: python
+
+    def reset_listener_queue():
+        listener_queue.clear()
+
+So, both ends of the deferred chain have now dropped their references, and the
+deferred chain is now orphaned, and will be garbage-collected at some point.
+Note that ``await_something_interesting`` is a generator function, and when
+Python garbage-collects generator functions, it gives them a chance to clean
+up by making the ``yield`` raise a ``GeneratorExit`` exception. In our case,
+that means that the ``__exit__`` handler of ``PreserveLoggingContext`` will
+carefully restore the request context, but there is now nothing waiting for
+its return, so the request context is never cleared.
+
+To reiterate, this problem only arises when *both* ends of a deferred chain
+are dropped. Dropping the the reference to a deferred you're supposed to be
+calling is probably bad practice, so this doesn't actually happen too much.
+Unfortunately, when it does happen, it will lead to leaked logcontexts which
+are incredibly hard to track down.
diff --git a/synapse/rest/client/v1/login.py b/synapse/rest/client/v1/login.py
index 0010699d31..f6b4a85e40 100644
--- a/synapse/rest/client/v1/login.py
+++ b/synapse/rest/client/v1/login.py
@@ -27,7 +27,7 @@ from twisted.web.client import PartialDownloadError
 
 from synapse.api.errors import Codes, LoginError, SynapseError
 from synapse.http.server import finish_request
-from synapse.http.servlet import parse_json_object_from_request
+from synapse.http.servlet import RestServlet, parse_json_object_from_request
 from synapse.types import UserID
 from synapse.util.msisdn import phone_number_to_msisdn
 
@@ -83,6 +83,7 @@ class LoginRestServlet(ClientV1RestServlet):
     PATTERNS = client_path_patterns("/login$")
     SAML2_TYPE = "m.login.saml2"
     CAS_TYPE = "m.login.cas"
+    SSO_TYPE = "m.login.sso"
     TOKEN_TYPE = "m.login.token"
     JWT_TYPE = "m.login.jwt"
 
@@ -105,6 +106,10 @@ class LoginRestServlet(ClientV1RestServlet):
         if self.saml2_enabled:
             flows.append({"type": LoginRestServlet.SAML2_TYPE})
         if self.cas_enabled:
+            flows.append({"type": LoginRestServlet.SSO_TYPE})
+
+            # we advertise CAS for backwards compat, though MSC1721 renamed it
+            # to SSO.
             flows.append({"type": LoginRestServlet.CAS_TYPE})
 
             # While its valid for us to advertise this login type generally,
@@ -384,11 +389,11 @@ class SAML2RestServlet(ClientV1RestServlet):
         defer.returnValue((200, {"status": "not_authenticated"}))
 
 
-class CasRedirectServlet(ClientV1RestServlet):
-    PATTERNS = client_path_patterns("/login/cas/redirect", releases=())
+class CasRedirectServlet(RestServlet):
+    PATTERNS = client_path_patterns("/login/(cas|sso)/redirect")
 
     def __init__(self, hs):
-        super(CasRedirectServlet, self).__init__(hs)
+        super(CasRedirectServlet, self).__init__()
         self.cas_server_url = hs.config.cas_server_url.encode('ascii')
         self.cas_service_url = hs.config.cas_service_url.encode('ascii')
 
diff --git a/synapse/static/client/login/index.html b/synapse/static/client/login/index.html
index 96c8723cab..bcb6bc6bb7 100644
--- a/synapse/static/client/login/index.html
+++ b/synapse/static/client/login/index.html
@@ -12,35 +12,30 @@
         <h1>Log in with one of the following methods</h1>
 
         <span id="feedback" style="color: #f00"></span>
-        <br/>
-        <br/>
 
         <div id="loading">
             <img src="spinner.gif" />
         </div>
 
-        <div id="cas_flow" class="login_flow" style="display:none"
-                onclick="gotoCas(); return false;">
-            CAS Authentication: <button id="cas_button" style="margin: 10px">Log in</button>
+        <div id="sso_flow" class="login_flow" style="display:none">
+            Single-sign on:
+            <form id="sso_form" action="/_matrix/client/r0/login/sso/redirect" method="get">
+                <input id="sso_redirect_url" type="hidden" name="redirectUrl" value=""/>
+                <input type="submit" value="Log in"/>
+            </form>
         </div>
 
-        <br/>
-
-        <form id="password_form" class="login_flow" style="display:none"
-                onsubmit="matrixLogin.password_login(); return false;">
-            <div>
-                Password Authentication:<br/>
-
-                <div style="text-align: center">
-                    <input id="user_id" size="32" type="text" placeholder="Matrix ID (e.g. bob)" autocapitalize="off" autocorrect="off" />
-                    <br/>
-                    <input id="password" size="32" type="password" placeholder="Password"/>
-                    <br/>
+        <div id="password_flow" class="login_flow" style="display:none">
+            Password Authentication:
+            <form onsubmit="matrixLogin.password_login(); return false;">
+                <input id="user_id" size="32" type="text" placeholder="Matrix ID (e.g. bob)" autocapitalize="off" autocorrect="off" />
+                <br/>
+                <input id="password" size="32" type="password" placeholder="Password"/>
+                <br/>
 
-                    <button type="submit" style="margin: 10px">Log in</button>
-                </div>
-            </div>
-        </form>
+                <input type="submit" value="Log in"/>
+            </form>
+        </div>
 
         <div id="no_login_types" type="button" class="login_flow" style="display:none">
             Log in currently unavailable.
diff --git a/synapse/static/client/login/js/login.js b/synapse/static/client/login/js/login.js
index bfb7386035..3a958749a1 100644
--- a/synapse/static/client/login/js/login.js
+++ b/synapse/static/client/login/js/login.js
@@ -1,7 +1,8 @@
 window.matrixLogin = {
-    endpoint: location.origin + "/_matrix/client/api/v1/login",
+    endpoint: location.origin + "/_matrix/client/r0/login",
     serverAcceptsPassword: false,
-    serverAcceptsCas: false
+    serverAcceptsCas: false,
+    serverAcceptsSso: false,
 };
 
 var submitPassword = function(user, pwd) {
@@ -40,12 +41,6 @@ var errorFunc = function(err) {
     }
 };
 
-var gotoCas = function() {
-    var this_page = window.location.origin + window.location.pathname;
-    var redirect_url = matrixLogin.endpoint + "/cas/redirect?redirectUrl=" + encodeURIComponent(this_page);
-    window.location.replace(redirect_url);
-}
-
 var setFeedbackString = function(text) {
     $("#feedback").text(text);
 };
@@ -53,12 +48,18 @@ var setFeedbackString = function(text) {
 var show_login = function() {
     $("#loading").hide();
 
+    var this_page = window.location.origin + window.location.pathname;
+    $("#sso_redirect_url").val(encodeURIComponent(this_page));
+
     if (matrixLogin.serverAcceptsPassword) {
-        $("#password_form").show();
+        $("#password_flow").show();
     }
 
-    if (matrixLogin.serverAcceptsCas) {
-        $("#cas_flow").show();
+    if (matrixLogin.serverAcceptsSso) {
+        $("#sso_flow").show();
+    } else if (matrixLogin.serverAcceptsCas) {
+        $("#sso_form").attr("action", "/_matrix/client/r0/login/cas/redirect");
+        $("#sso_flow").show();
     }
 
     if (!matrixLogin.serverAcceptsPassword && !matrixLogin.serverAcceptsCas) {
@@ -67,8 +68,8 @@ var show_login = function() {
 };
 
 var show_spinner = function() {
-    $("#password_form").hide();
-    $("#cas_flow").hide();
+    $("#password_flow").hide();
+    $("#sso_flow").hide();
     $("#no_login_types").hide();
     $("#loading").show();
 };
@@ -84,7 +85,10 @@ var fetch_info = function(cb) {
                 matrixLogin.serverAcceptsCas = true;
                 console.log("Server accepts CAS");
             }
-
+            if ("m.login.sso" === flow.type) {
+                matrixLogin.serverAcceptsSso = true;
+                console.log("Server accepts SSO");
+            }
             if ("m.login.password" === flow.type) {
                 matrixLogin.serverAcceptsPassword = true;
                 console.log("Server accepts password");
diff --git a/synapse/static/client/login/style.css b/synapse/static/client/login/style.css
index 73da0b5117..1cce5ed950 100644
--- a/synapse/static/client/login/style.css
+++ b/synapse/static/client/login/style.css
@@ -19,30 +19,23 @@ a:hover   { color: #000; }
 a:active  { color: #000; }
 
 input {
-   width: 90%
-}
-
-textarea, input {
-   font-family: inherit;
-   font-size: inherit;
    margin: 5px;
 }
 
-.smallPrint {
-    color: #888;
-    font-size: 9pt ! important;
-    font-style: italic ! important;
+textbox, input[type="text"], input[type="password"] {
+   width: 90%;
 }
 
-.g-recaptcha div {
-    margin: auto;
+form {
+    text-align: center;
+    margin: 10px 0 0 0;
 }
 
 .login_flow {
+    width: 300px;
     text-align: left;
     padding: 10px;
     margin-bottom: 40px;
-    display: inline-block;
 
     -webkit-border-radius: 10px;
     -moz-border-radius: 10px;
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/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
diff --git a/tests/unittest.py b/tests/unittest.py
index a9ce57da9a..a191cccc29 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
@@ -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)
@@ -115,6 +123,16 @@ 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."""