Merge branch 'develop' into rav/saml_mapping_work

1 files changed, 0 insertions, 498 deletions

diff --git a/docs/log_contexts.rst b/docs/log_contexts.rst
deleted file mode 100644
index 4502cd9454..0000000000
--- a/docs/log_contexts.rst
+++ /dev/null
@@ -1,498 +0,0 @@
-Log Contexts
-============
-
-.. contents::
-
-To help track the processing of individual requests, synapse uses a
-'log context' to track which request it is handling at any given moment. This
-is done via a thread-local variable; a ``logging.Filter`` is then used to fish
-the information back out of the thread-local variable and add it to each log
-record.
-
-Logcontexts are also used for CPU and database accounting, so that we can track
-which requests were responsible for high CPU use or database activity.
-
-The ``synapse.logging.context`` module provides a facilities for managing the
-current log context (as well as providing the ``LoggingContextFilter`` class).
-
-Deferreds make the whole thing complicated, so this document describes how it
-all works, and how to write code which follows the rules.
-
-Logcontexts without Deferreds
------------------------------
-
-In the absence of any Deferred voodoo, things are simple enough. As with any
-code of this nature, the rule is that our function should leave things as it
-found them:
-
-.. code:: python
-
-    from synapse.logging import context         # omitted from future snippets
-
-    def handle_request(request_id):
-        request_context = context.LoggingContext()
-
-        calling_context = context.LoggingContext.current_context()
-        context.LoggingContext.set_current_context(request_context)
-        try:
-            request_context.request = request_id
-            do_request_handling()
-            logger.debug("finished")
-        finally:
-            context.LoggingContext.set_current_context(calling_context)
-
-    def do_request_handling():
-        logger.debug("phew")  # this will be logged against request_id
-
-
-LoggingContext implements the context management methods, so the above can be
-written much more succinctly as:
-
-.. code:: python
-
-    def handle_request(request_id):
-        with context.LoggingContext() as request_context:
-            request_context.request = request_id
-            do_request_handling()
-            logger.debug("finished")
-
-    def do_request_handling():
-        logger.debug("phew")
-
-
-Using logcontexts with Deferreds
---------------------------------
-
-Deferreds — and in particular, ``defer.inlineCallbacks`` — break
-the linear flow of code so that there is no longer a single entry point where
-we should set the logcontext and a single exit point where we should remove it.
-
-Consider the example above, where ``do_request_handling`` needs to do some
-blocking operation, and returns a deferred:
-
-.. code:: python
-
-    @defer.inlineCallbacks
-    def handle_request(request_id):
-        with context.LoggingContext() as request_context:
-            request_context.request = request_id
-            yield do_request_handling()
-            logger.debug("finished")
-
-
-In the above flow:
-
-* The logcontext is set
-* ``do_request_handling`` is called, and returns a deferred
-* ``handle_request`` yields the deferred
-* The ``inlineCallbacks`` wrapper of ``handle_request`` returns a deferred
-
-So we have stopped processing the request (and will probably go on to start
-processing the next), without clearing the logcontext.
-
-To circumvent this problem, synapse code assumes that, wherever you have a
-deferred, you will want to yield on it. To that end, whereever functions return
-a deferred, we adopt the following conventions:
-
-**Rules for functions returning deferreds:**
-
-  * If the deferred is already complete, the function returns with the same
-    logcontext it started with.
-  * If the deferred is incomplete, the function clears the logcontext before
-    returning; when the deferred completes, it restores the logcontext before
-    running any callbacks.
-
-That sounds complicated, but actually it means a lot of code (including the
-example above) "just works". There are two cases:
-
-* If ``do_request_handling`` returns a completed deferred, then the logcontext
-  will still be in place. In this case, execution will continue immediately
-  after the ``yield``; the "finished" line will be logged against the right
-  context, and the ``with`` block restores the original context before we
-  return to the caller.
-
-* If the returned deferred is incomplete, ``do_request_handling`` clears the
-  logcontext before returning. The logcontext is therefore clear when
-  ``handle_request`` yields the deferred. At that point, the ``inlineCallbacks``
-  wrapper adds a callback to the deferred, and returns another (incomplete)
-  deferred to the caller, and it is safe to begin processing the next request.
-
-  Once ``do_request_handling``'s deferred completes, it will reinstate the
-  logcontext, before running the callback added by the ``inlineCallbacks``
-  wrapper. That callback runs the second half of ``handle_request``, so again
-  the "finished" line will be logged against the right
-  context, and the ``with`` block restores the original context.
-
-As an aside, it's worth noting that ``handle_request`` follows our rules -
-though that only matters if the caller has its own logcontext which it cares
-about.
-
-The following sections describe pitfalls and helpful patterns when implementing
-these rules.
-
-Always yield your deferreds
----------------------------
-
-Whenever you get a deferred back from a function, you should ``yield`` on it
-as soon as possible. (Returning it directly to your caller is ok too, if you're
-not doing ``inlineCallbacks``.) Do not pass go; do not do any logging; do not
-call any other functions.
-
-.. code:: python
-
-    @defer.inlineCallbacks
-    def fun():
-        logger.debug("starting")
-        yield do_some_stuff()       # just like this
-
-        d = more_stuff()
-        result = yield d            # also fine, of course
-
-        return result
-
-    def nonInlineCallbacksFun():
-        logger.debug("just a wrapper really")
-        return do_some_stuff()      # this is ok too - the caller will yield on
-                                    # it anyway.
-
-Provided this pattern is followed all the way back up to the callchain to where
-the logcontext was set, this will make things work out ok: provided
-``do_some_stuff`` and ``more_stuff`` follow the rules above, then so will
-``fun`` (as wrapped by ``inlineCallbacks``) and ``nonInlineCallbacksFun``.
-
-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 context. (Normally, other
-things will break, more obviously, if you forget to ``yield``, so this tends
-not to be a major problem in practice.)
-
-Of course sometimes you need to do something a bit fancier with your Deferreds
-- not all code follows the linear A-then-B-then-C pattern. Notes on
-implementing more complex patterns are in later sections.
-
-Where you create a new Deferred, make it follow the rules
----------------------------------------------------------
-
-Most of the time, a Deferred comes from another synapse function. Sometimes,
-though, we need to make up a new Deferred, or we get a Deferred back from
-external code. We need to make it follow our rules.
-
-The easy way to do it is with a combination of ``defer.inlineCallbacks``, and
-``context.PreserveLoggingContext``. Suppose we want to implement ``sleep``,
-which returns a deferred which will run its callbacks after a given number of
-seconds. That might look like:
-
-.. code:: python
-
-    # not a logcontext-rules-compliant function
-    def get_sleep_deferred(seconds):
-        d = defer.Deferred()
-        reactor.callLater(seconds, d.callback, None)
-        return d
-
-That doesn't follow the rules, but we can fix it by wrapping it with
-``PreserveLoggingContext`` and ``yield`` ing on it:
-
-.. code:: python
-
-    @defer.inlineCallbacks
-    def sleep(seconds):
-        with PreserveLoggingContext():
-            yield get_sleep_deferred(seconds)
-
-This technique works equally for external functions which return deferreds,
-or deferreds we have made ourselves.
-
-You can also use ``context.make_deferred_yieldable``, which just does the
-boilerplate for you, so the above could be written:
-
-.. code:: python
-
-    def sleep(seconds):
-        return context.make_deferred_yieldable(get_sleep_deferred(seconds))
-
-
-Fire-and-forget
----------------
-
-Sometimes you want to fire off a chain of execution, but not wait for its
-result. That might look a bit like this:
-
-.. code:: python
-
-    @defer.inlineCallbacks
-    def do_request_handling():
-        yield foreground_operation()
-
-        # *don't* do this
-        background_operation()
-
-        logger.debug("Request handling complete")
-
-    @defer.inlineCallbacks
-    def background_operation():
-        yield first_background_step()
-        logger.debug("Completed first step")
-        yield second_background_step()
-        logger.debug("Completed second step")
-
-The above code does a couple of steps in the background after
-``do_request_handling`` has finished. The log lines are still logged against
-the ``request_context`` logcontext, which may or may not be desirable. There
-are two big problems with the above, however. The first problem is that, if
-``background_operation`` returns an incomplete Deferred, it will expect its
-caller to ``yield`` immediately, so will have cleared the logcontext. In this
-example, that means that 'Request handling complete' will be logged without any
-context.
-
-The second problem, which is potentially even worse, is that when the Deferred
-returned by ``background_operation`` completes, it will restore the original
-logcontext. There is nothing waiting on that Deferred, so the logcontext will
-leak into the reactor and possibly get attached to some arbitrary future
-operation.
-
-There are two potential solutions to this.
-
-One option is to surround the call to ``background_operation`` with a
-``PreserveLoggingContext`` call. That will reset the logcontext before
-starting ``background_operation`` (so the context restored when the deferred
-completes will be the empty logcontext), and will restore the current
-logcontext before continuing the foreground process:
-
-.. code:: python
-
-    @defer.inlineCallbacks
-    def do_request_handling():
-        yield foreground_operation()
-
-        # start background_operation off in the empty logcontext, to
-        # avoid leaking the current context into the reactor.
-        with PreserveLoggingContext():
-            background_operation()
-
-        # this will now be logged against the request context
-        logger.debug("Request handling complete")
-
-Obviously that option means that the operations done in
-``background_operation`` would be not be logged against a logcontext (though
-that might be fixed by setting a different logcontext via a ``with
-LoggingContext(...)`` in ``background_operation``).
-
-The second option is to use ``context.run_in_background``, which wraps a
-function so that it doesn't reset the logcontext even when it returns an
-incomplete deferred, and adds a callback to the returned deferred to reset the
-logcontext. In other words, it turns a function that follows the Synapse rules
-about logcontexts and Deferreds into one which behaves more like an external
-function — the opposite operation to that described in the previous section.
-It can be used like this:
-
-.. code:: python
-
-    @defer.inlineCallbacks
-    def do_request_handling():
-        yield foreground_operation()
-
-        context.run_in_background(background_operation)
-
-        # this will now be logged against the request context
-        logger.debug("Request handling complete")
-
-Passing synapse deferreds into third-party functions
-----------------------------------------------------
-
-A typical example of this is where we want to collect together two or more
-deferred via ``defer.gatherResults``:
-
-.. code:: python
-
-    d1 = operation1()
-    d2 = operation2()
-    d3 = defer.gatherResults([d1, d2])
-
-This is really a variation of the fire-and-forget problem above, in that we are
-firing off ``d1`` and ``d2`` without yielding on them. The difference
-is that we now have third-party code attached to their callbacks. Anyway either
-technique given in the `Fire-and-forget`_ section will work.
-
-Of course, the new Deferred returned by ``gatherResults`` needs to be wrapped
-in order to make it follow the logcontext rules before we can yield it, as
-described in `Where you create a new Deferred, make it follow the rules`_.
-
-So, option one: reset the logcontext before starting the operations to be
-gathered:
-
-.. code:: python
-
-    @defer.inlineCallbacks
-    def do_request_handling():
-        with PreserveLoggingContext():
-            d1 = operation1()
-            d2 = operation2()
-            result = yield defer.gatherResults([d1, d2])
-
-In this case particularly, though, option two, of using
-``context.preserve_fn`` almost certainly makes more sense, so that
-``operation1`` and ``operation2`` are both logged against the original
-logcontext. This looks like:
-
-.. code:: python
-
-    @defer.inlineCallbacks
-    def do_request_handling():
-        d1 = context.preserve_fn(operation1)()
-        d2 = context.preserve_fn(operation2)()
-
-        with PreserveLoggingContext():
-            result = yield defer.gatherResults([d1, d2])
-
-
-Was all this really necessary?
-------------------------------
-
-The conventions used work fine for a linear flow where everything happens in
-series via ``defer.inlineCallbacks`` and ``yield``, but are certainly tricky to
-follow for any more exotic flows. It's hard not to wonder if we could have done
-something else.
-
-We're not going to rewrite Synapse now, so the following is entirely of
-academic interest, but I'd like to record some thoughts on an alternative
-approach.
-
-I briefly prototyped some code following an alternative set of rules. I think
-it would work, but I certainly didn't get as far as thinking how it would
-interact with concepts as complicated as the cache descriptors.
-
-My alternative rules were:
-
-* functions always preserve the logcontext of their caller, whether or not they
-  are returning a Deferred.
-
-* Deferreds returned by synapse functions run their callbacks in the same
-  context as the function was orignally called in.
-
-The main point of this scheme is that everywhere that sets the logcontext is
-responsible for clearing it before returning control to the reactor.
-
-So, for example, if you were the function which started a ``with
-LoggingContext`` block, you wouldn't ``yield`` within it — instead you'd start
-off the background process, and then leave the ``with`` block to wait for it:
-
-.. code:: python
-
-    def handle_request(request_id):
-        with context.LoggingContext() as request_context:
-            request_context.request = request_id
-            d = do_request_handling()
-
-        def cb(r):
-            logger.debug("finished")
-
-        d.addCallback(cb)
-        return d
-
-(in general, mixing ``with LoggingContext`` blocks and
-``defer.inlineCallbacks`` in the same function leads to slighly
-counter-intuitive code, under this scheme).
-
-Because we leave the original ``with`` block as soon as the Deferred is
-returned (as opposed to waiting for it to be resolved, as we do today), the
-logcontext is cleared before control passes back to the reactor; so if there is
-some code within ``do_request_handling`` which needs to wait for a Deferred to
-complete, there is no need for it to worry about clearing the logcontext before
-doing so:
-
-.. code:: python
-
-    def handle_request():
-        r = do_some_stuff()
-        r.addCallback(do_some_more_stuff)
-        return r
-
-— and provided ``do_some_stuff`` follows the rules of returning a Deferred which
-runs its callbacks in the original logcontext, all is happy.
-
-The business of a Deferred which runs its callbacks in the original logcontext
-isn't hard to achieve — we have it today, in the shape of
-``context._PreservingContextDeferred``:
-
-.. code:: python
-
-    def do_some_stuff():
-        deferred = do_some_io()
-        pcd = _PreservingContextDeferred(LoggingContext.current_context())
-        deferred.chainDeferred(pcd)
-        return pcd
-
-It turns out that, thanks to the way that Deferreds chain together, we
-automatically get the property of a context-preserving deferred with
-``defer.inlineCallbacks``, provided the final Defered the function ``yields``
-on has that property. So we can just write:
-
-.. code:: python
-
-    @defer.inlineCallbacks
-    def handle_request():
-        yield do_some_stuff()
-        yield do_some_more_stuff()
-
-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.