diff options
| -rw-r--r-- | changelog.d/4190.misc | 1 | ||||
| -rw-r--r-- | changelog.d/4209.misc | 1 | ||||
| -rw-r--r-- | changelog.d/4220.feature | 1 | ||||
| -rw-r--r-- | changelog.d/4227.misc | 1 | ||||
| -rw-r--r-- | docs/log_contexts.rst | 58 | ||||
| -rw-r--r-- | synapse/rest/client/v1/login.py | 13 | ||||
| -rw-r--r-- | synapse/static/client/login/index.html | 37 | ||||
| -rw-r--r-- | synapse/static/client/login/js/login.js | 32 | ||||
| -rw-r--r-- | synapse/static/client/login/style.css | 19 | ||||
| -rw-r--r-- | tests/crypto/test_keyring.py | 18 | ||||
| -rw-r--r-- | tests/rest/media/v1/test_media_storage.py | 3 | ||||
| -rw-r--r-- | tests/unittest.py | 24 |
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.""" |