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
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.
synapse.logging.context module provides a facilities for managing
the current log context (as well as providing the
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:
from synapse.logging import context # omitted from future snippets def handle_request(request_id): request_context = context.LoggingContext() calling_context = context.set_current_context(request_context) try: request_context.request = request_id do_request_handling() logger.debug("finished") finally: context.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:
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")
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:
@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_handlingis called, and returns a deferred
handle_requestyields the deferred
handle_requestreturns 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:
do_request_handlingreturns 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
withblock restores the original context before we return to the caller.
If the returned deferred is incomplete,
do_request_handlingclears the logcontext before returning. The logcontext is therefore clear when
handle_requestyields the deferred. At that point, the
inlineCallbackswrapper adds a callback to the deferred, and returns another (incomplete) deferred to the caller, and it is safe to begin processing the next request.
do_request_handling's deferred completes, it will reinstate the logcontext, before running the callback added by the
inlineCallbackswrapper. That callback runs the second half of
handle_request, so again the "finished" line will be logged against the right context, and the
withblock 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
The following sections describe pitfalls and helpful patterns when implementing these rules.
Whenever you get a deferred back from a function, you should
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.
@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:
more_stuff follow the rules above, then
fun (as wrapped by
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.
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
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:
# 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
yield ing on it:
@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:
def sleep(seconds): return context.make_deferred_yieldable(get_sleep_deferred(seconds))
Sometimes you want to fire off a chain of execution, but not wait for its result. That might look a bit like this:
@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
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
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:
@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
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:
@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")
A typical example of this is where we want to collect together two or
more deferred via
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
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
So, option one: reset the logcontext before starting the operations to be gathered:
@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
operation2 are both logged against the original
logcontext. This looks like:
@defer.inlineCallbacks def do_request_handling(): d1 = context.preserve_fn(operation1)() d2 = context.preserve_fn(operation2)() with PreserveLoggingContext(): result = yield defer.gatherResults([d1, d2])
The conventions used work fine for a linear flow where everything
happens in series via
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
to wait for it:
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:
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
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
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:
@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.
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:
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:
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
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
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.