log_contexts.md

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 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:

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 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:

@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.