+ +

Log Contexts

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 facilities for managing +the current log context (as well as providing the LoggingContextFilter +class).

Asynchronous functions make the whole thing complicated, so this document describes +how it all works, and how to write code which follows the rules.

In this document, "awaitable" refers to any object which can be awaited. In the context of +Synapse, that normally means either a coroutine or a Twisted +Deferred.

Logcontexts without asynchronous code

In the absence of any asynchronous 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")
+

Using logcontexts with awaitables

Awaitables 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 an awaitable:

async def handle_request(request_id):
+    with context.LoggingContext() as request_context:
+        request_context.request = request_id
+        await do_request_handling()
+        logger.debug("finished")
+

In the above flow:

The logcontext is set
do_request_handling is called, and returns an awaitable
handle_request awaits the awaitable
Execution of handle_request is suspended

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 +an awaitable, you will want to await it. To that end, whereever +functions return awaitables, we adopt the following conventions:

Rules for functions returning awaitables:

+
+
If the awaitable is already complete, the function returns with the +same logcontext it started with.
+
If the awaitable is incomplete, the function clears the logcontext +before returning; when the awaitable 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 awaitable, then the +logcontext will still be in place. In this case, execution will +continue immediately after the await; 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 awaitable is incomplete, do_request_handling clears +the logcontext before returning. The logcontext is therefore clear +when handle_request awaits the awaitable.
+
Once do_request_handling's awaitable completes, it will reinstate +the logcontext, before running 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 await your awaitables

Whenever you get an awaitable back from a function, you should await on +it as soon as possible. Do not pass go; do not do any logging; do not +call any other functions.

async def fun():
+    logger.debug("starting")
+    await do_some_stuff()       # just like this
+
+    coro = more_stuff()
+    result = await coro         # also fine, of course
+
+    return result
+

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.

It's all too easy to forget to await: for instance if we forgot that +do_some_stuff returned an awaitable, 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 +await, so this tends not to be a major problem in practice.)

Of course sometimes you need to do something a bit fancier with your +awaitable - 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 awaitable, make it follow the rules

Most of the time, an awaitable comes from another synapse function. +Sometimes, though, we need to make up a new awaitable, or we get an awaitable +back from external code. We need to make it follow our rules.

The easy way to do it is by using context.make_deferred_yieldable. 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 calling it through +context.make_deferred_yieldable:

async def sleep(seconds):
+    return await 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:

async def do_request_handling():
+    await foreground_operation()
+
+    # *don't* do this
+    background_operation()
+
+    logger.debug("Request handling complete")
+
+async def background_operation():
+    await first_background_step()
+    logger.debug("Completed first step")
+    await 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 +awaitable, it will expect its caller to await 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 +awaitable returned by background_operation completes, it will restore +the original logcontext. There is nothing waiting on that awaitable, 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:

async def do_request_handling():
+    await 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 awaitable, and adds a callback to the returned awaitable to +reset the logcontext. In other words, it turns a function that follows +the Synapse rules about logcontexts and awaitables 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:

async def do_request_handling():
+    await 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 awaitables via defer.gatherResults:

a1 = operation1()
+a2 = operation2()
+a3 = defer.gatherResults([a1, a2])
+

This is really a variation of the fire-and-forget problem above, in that +we are firing off a1 and a2 without awaiting 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 awaitable returned by gather 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 awaitable, make it +follow the +rules.

So, option one: reset the logcontext before starting the operations to +be gathered:

async def do_request_handling():
+    with PreserveLoggingContext():
+        a1 = operation1()
+        a2 = operation2()
+        result = await defer.gatherResults([a1, a2])
+

In this case particularly, though, option two, of using +context.run_in_background almost certainly makes more sense, so that +operation1 and operation2 are both logged against the original +logcontext. This looks like:

async def do_request_handling():
+    a1 = context.run_in_background(operation1)
+    a2 = context.run_in_background(operation2)
+
+    result = await make_deferred_yieldable(defer.gatherResults([a1, a2]))
+

A note on garbage-collection of awaitable chains

It turns out that our logcontext rules do not play nicely with awaitable +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")
+
+async def await_something_interesting():
+    new_awaitable = defer.Deferred()
+    listener_queue.append(new_awaitable)
+
+    with PreserveLoggingContext():
+        await new_awaitable
+

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 awaitable chain have now dropped their references, +and the awaitable chain is now orphaned, and will be garbage-collected at +some point. Note that await_something_interesting is a coroutine, +which Python implements as a generator function. When Python +garbage-collects generator functions, it gives them a chance to +clean up by making the await (or 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 awaitable +chain are dropped. Dropping the the reference to an awaitable you're +supposed to be awaiting is 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.

+ +