Add integration information for Django

[anirvan-majumdar]

This is a reference document and not a bug.

We have recently deployed StructLog on our Django project and thought of sharing our learnings through the process of doing so.

NOTE: It's been about 10 days since we've deployed StuctLog, so we are still in the process of exploring the full set of potential use-cases and challenges.

Motivation

We make use of ELK to centralise our logs from 9-10 application servers running Django. Our Django project is quite vast and has about 300k+ lines of code. To harness the power of ELK, we had to find some way to structure our log statements in a manner such that ELK could grok it.

With this need in mind, I was generally looking around for a solution that could help us address the problem of making log statements better.

Other requirements

• Progressive development: we didn't want to use something that would need all our log statements to be changed at one go. We wanted to make the transition one module at a time.

• Less verbose logger code: .format() has done its bit to help us write contextually rich log statements. But to pass around the contextual variables to maintain the context across the scope of a request-response cycle simply doesn't work.

Enter StructLog

Coming across StructLog, some of the immediate benefits were hard to resist and so we decided to give it a shot.

• Log statement as events: this made a lot of sense to us. Instead of verbose statements as logs, log events along with context data makes it much easier to have something like ELK crunch meaningful data from it.

• Support for JSON output format: instead of having to write complex GROK expressions in ELK, we could generate JSON logs which can be easily consumed by ELK.

• Bind/Unbind: a perfect solution for escaping from the hell of having to build verbose log statements using .format().

• Coloured logs: nice, coloured logs in the dev environment 😃

StuctLog and Django

Keeping in mind the need to have a progressive plan for adopting StructLog in our Django project, here are the changes we made...

1. settings.py - wrapping the standard logger

In our settings.py file, we added the following block after defining the LOGGING configuration:

# struct log setup
processors = [
    # structlog.stdlib.add_log_level,
    structlog.stdlib.PositionalArgumentsFormatter(),
    # timestamper,
    structlog.processors.StackInfoRenderer(),
    structlog.processors.format_exc_info,
    structlog.processors.UnicodeEncoder(),
    # structlog.dev.ConsoleRenderer(pad_event=20),
    structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
]

structlog.configure_once(
    processors=processors,
    context_class=structlog.threadlocal.wrap_dict(dict),
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=common.utilities.logger_wrapper.BoundLoggerWrapper,
    # wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)

This block of code sets up the processors required for generating the log statements in a particular format. The lines commented above can be uncommented, but then you should make sure that the LOGGING handlers format attribute makes use of StructLog. We were fine with the structure of our logger statements and only wanted the log message part to be customised.

In the configure_once section, we ensure that loggers are used in a ThreadLocal context and we make use a custom BoundLogger class (explained later) to alter the handling of the context dictionary maintained by each logger.

After updating the settings.py, you can select any module and replace your standard logger declaration with a wrapped version to make use of StructLog like so:

from structlog import wrap_logger

logger = wrap_logger(logger=logging.getLogger(__name__))

You can pretty much leave it at that and everything will work just fine. However, we went ahead and started structuring every log statement as an event. So, something like:

logger.info('User has logged in. Username={}'.format(username))

became,

logger.info('user_logged_in', username=username)

2. Context variable bind/unbind handling

One of the best features of StructLog is to associate context variables in the context of an execution path. For Django, this means that for each request/response cycle you can bind used context values so that all log statements printed in the cycle have those variable printed.

The flip side to binding context side is that you need to remember to unbind the values. Each logger instance instantiated in Django application is a singleton. If the context variables for a particular request-response cycle aren't unbound, they will appear for the next unrelated request-response cycle.

Using StructLog's unbind method on the logger wrapper, you can remove these bound variables. This is easy to do within the scope of a method or an iterator. But it can be quite non-trivial to manage this when the execution branches out into multiple different paths.

To ensure that the context is cleared for each request-response cycle, we wrote a simple middleware class like so:

class RequestLoggingMiddleware(object):

    def process_request(self, request):
        # extract common headers
        logger_values = dict(request_id=str(uuid.uuid4()), user_agent=request.META.get('HTTP_USER_AGENT'))
        logger.new(**logger_values)

One other trouble we ran into is a KeyError that is thrown when you try to unbind a variable that has already been removed from the context of the StructLog instance. To handle this we wrote a wrapper class (see settings.py config) to override the context value lookup:

from structlog.stdlib import BoundLogger

class BoundLoggerWrapper(BoundLogger):
    def unbind(self, *keys):
        try:
            return super(BoundLoggerWrapper, self).unbind(*keys)
        except KeyError:
            return self.bind()

NOTE: In version 18.2, it won't be required to do this. A try_unbind() method will be available on the standard structlog.stdlib.BoundLogger class. Refer #171

With these few changes, we have been making use of StructLog in our Django project.
Hope this helps you in some way if you're planning to do something similar.

[hynek]

Thanks for this, I have expanded the Django section slightly and linked back here if someone wants the details!

[viperfx]

@anirvan-majumdar does your logging include the filename and line number of the source log? If so, how did you include it?