This is a reference document andnot 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 couldgrok it.

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

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 asevents: this made a lot of sense to us. Instead of verbose statements as logs, logevents 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 oursettings.py file, we added the following block after defining theLOGGING configuration:

# struct log setupprocessors= [# 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 theprocessors required for generating the log statements in a particular format. The lines commented above can be uncommented, but then you should make sure that theLOGGING handlersformat attribute makes use of StructLog. We were fine with the structure of our logger statements and only wanted thelog message part to be customised.

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

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

fromstructlogimportwrap_loggerlogger=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 anevent. 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 canbind 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 tounbind the values. Eachlogger instance instantiated in Django application is asingleton. 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'sunbind 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 simplemiddleware class like so:

classRequestLoggingMiddleware(object):defprocess_request(self,request):# extract common headerslogger_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 aKeyError that is thrown when you try tounbind a variable that has already been removed from the context of the StructLog instance. To handle this we wrote awrapper class (seesettings.py config) to override the context value lookup:

fromstructlog.stdlibimportBoundLoggerclassBoundLoggerWrapper(BoundLogger):defunbind(self,*keys):try:returnsuper(BoundLoggerWrapper,self).unbind(*keys)exceptKeyError:returnself.bind()

NOTE: In version 18.2, it won't be required to do this. Atry_unbind() method will be available on the standardstructlog.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.