Python logging best practices
with JSON steroids

In critical systems such as planes, elevators or trains, there are boxes logging everything, all the time. Because if the system crashes, somebody will have to understand what happened to prevent further occurrences. The same goes for mobile or web apps: if it matters to at least one user, you can be sure that in case of failure a guy somewhere will be in charge of understanding why it happened and how to patch it. Plus, it’s usually the same guy that needs to answer on a daily basis any technical or business questions related to this very system.

With this in mind, I listed below all the good Python logging practices I know of to help you get the best visibility in your system. The first part will cover the basics, while the second part is for the adventurous, willing to get the most out of their Python logs by adding context, metrics or using log analytics tools.

So, let’s get going!

Python Logging Good Practices

1) Use the standard Python logging module

It really is not recommended to use “print” as your standard logging function:

print 'Do not rely on this example!'

Instead, the Python community has created a Python logging module so everyone can rely on the same standard.

a. Why does it matter?

The logging module lets you control the severity level you want to actually produce depending on output appenders and deployment (dev, staging, production, …). Logger events generated are also place and time specific, giving you:

  • Date
  • Module name
  • Logger name
  • Function name
  • Line number

These pieces of information are all extremely useful while troubleshooting applications.

In addition, when somebody else uses your modules they’ll expect to be able to leverage the log events they produce.

b. So how do I do it?

import logging
logging.basicConfig(level=logging.DEBUG)
logger = logging.getLogger(__name__)

#Info level msg
logger.info('This is a standard message')
#Debug level msg
logger.debug('This is what you may want to see... sometimes...')
#Warning level msg
logger.info('This is what you are usually not happy to see')

If you run it you should see the following appearing:

INFO:__main__:This is a standard message
DEBUG:__main__:This is what you may want to see... sometimes...
WARN:__main__:This is what you are usually not happy to see

If you don’t want to receive all log entries in DEBUG level, raise the base configuration level to INFO or WARN.

2) Log everywhere you can

Now that you have a good logging library to rely on, the goal is to be able to use it as much as you can.

In other words, your code should provide as much information as it can at the right severity level. We often think of warn, severe and exception levels as signals for something that went wrong. However, if you wish to really explain past actions, do root-cause analyses or trace queries services, and log at INFO and DEBUG levels.

Let’s have a look at the example below: if you were to code the following piece, you would get traces from all the queries that go through some APIs.


def handle_query(request):
    logger.info('Starting request %s', request)

    # handle query here

    response = 'response'
    logger.info('Returning response: %s', response)

And in the developing stage, logging in DEBUG everywhere can help you understand a complex algorithm or do message tracing etc…

3) Stick to the standard logger name

Log entry origins can be identified if your log format displays the logger name. Given the useful information already provided, there is no reason to change the standard. When you get or create a logger simply use __name__ which is the current module name.

To illustrate, let’s say you call logger.getLogger(__name__) in the foo.bar.my_great_module. It would have exactly the same effect as calling logger.getLogger(“foo.bar.my_great_module“).

4) Capture all exceptions tracebacks

I’m not going to push for catching as many exceptions as you possibly can. But Python has the ability to provide the stack trace (called traceback) which are very useful to understand issues.

To capture them with Python logging:


import sys
try:
    f = open('myfile.txt')
    s = f.readline()
    i = int(s.strip())
except Exception, e:
    logger.error('Failed to read the file', exc_info=True)

The Python traceback then looks like:


ERROR:__main__:Failed to read the file
Traceback (most recent call last):
  File "mymodule.py", line 3, in module
    open('myfile.txt', 'rb')
IOError: [Errno 2] No such file or directory: 'myfile.txt'

5) Use logging configuration files

Configuring Python logging directly from code loses you a lot of flexibility when deploying on multiple servers. Luckily after Python 2.7, logging configurations can now be loaded from a dict, meaning you can lead from a JSON or YAML file.

Here is a YAML example from Victor Lin’s article:

version: 1
disable_existing_loggers: False
formatters:
   simple:
      format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s"

handlers:
   console:
       class: logging.StreamHandler
       level: DEBUG
       formatter: simple
       stream: ext://sys.stdout

   info_file_handler:
   class: logging.handlers.RotatingFileHandler
       level: INFO 
       formatter: simple
       filename: info.log
       maxBytes: 10485760 # 10MB
       backupCount: 20
       encoding: utf8

 error_file_handler:
     class: logging.handlers.RotatingFileHandler
     level: ERROR 
     formatter: simple
     filename: errors.log
     maxBytes: 10485760 # 10MB
     backupCount: 20
     encoding: utf8

loggers:
     my_module:
         level: ERROR
         handlers: [console]
         propagate: no

root:
     level: INFO
      handlers: [console, info_file_handler, error_file_handler]

Let’s Add Some Steroids

So far, I’ve covered how Python logging should be at minimum… However, new logging techniques have emerged recently thanks to new log management tools such as on-premise systems Splunk, open source ones such as ELK (Elasticsearch, Logstash, Kibana) or SaaS ones such as Logmatic.io.

1) Log in JSON

Logging in JSON makes a lot of sense when your log data is consumed by machines. While custom log formats require complex parsers and may be subject to future changes, JSON structure brings flexibility and its hierarchy is directly understood and re-constructed by JSON parsers.

a. Custom format vs JSON format

Log sample with a custom format:

# Log formatted as "%(asctime) - %(name) - %(levelname) - %(message)"
2011-08-22 17:52:54,828 - lm.auth - WARN - No user currently authenticated.

The same log entry in JSON format:

{
   "funcName": "validate_user",
   "filename": "auth.py",
   "lineno": 362,
   "processName": "MainProcess",
   "module": "auth",
   "name": "lm.auth",
   "levelname": "WARNING",
   "message": "No user currently authenticated.",
   "asctime": "2011-08-22 17:52:54,828",
   "threadName": "MainThread"
}

As you can see, all the meta-attributes associated to the log event are automatically extracted from JSON parsers. What’s more, you can attach additional context such as its userId, customer (for multi tenant platforms for instance), metrics such as response time, etc… the JSON-ified log will display them all.

b. Multi-lined tracebacks

A big challenge when working with Log management tools is dealing with multi-line logging, especially multi-lined tracebacks, where it is hard to find originating events. Luckily in JSON, the traceback is totally embedded in the event.

{
 ...
 "exc_info": "Traceback (most recent call last):\n File \"test/write_in_console.py\", line 24, in exception_test\n raise Exception('test')\nException: test",
 ...
}

Thanks to a good log management tool, everything is displayed properly.

c. It all makes sense! So… How do I setup JSON format?

Unfortunately, the Python logging module does not contain any proper JSON formatter. That’s why the community is here, to help! You’ll can find a good JSON formatter in our Github.

Here is how to configure it:

import logmatic
import logging

logger = logging.getLogger()

handler = logging.StreamHandler()
handler.setFormatter(logmatic.JsonFormatter(extra={"hostname":socket.gethostname()}))

logger.addHandler(handler)
logger.setLevel(logging.INFO)

You probably also noticed that I added some extra context (the hostname) that is going to be attached to all the log events passed through this handler.

2) Add as much context as you need

Context matters! Adding context and metrics will bring your logging to the next level. It also prevents troubleshooting critical issues seem like a journey into the darkness.

a. Troubleshooting

A good log format combined with a good logging tool allow you to quickly spot and isolate log events emitted for serving a customer, severity level, and modules that emitted warnings. Troubleshooting times can be 5 to 10 times faster, allowing you to provide quick answers to customers!

Let’s add a customer name and the number of trials to my previous log:

logger.warn("No user currently authenticated.",
             extra={"customer": "my_beloved_customer", "login_name": "foo@bar.com"})

My previous JSON then becomes:

{
   "funcName": "validate_user",
   "filename": "auth.py",
   "lineno": 362,
   "processName": "MainProcess",
   "module": "auth",
   "name": "lm.auth",
   "levelname": "WARNING",
   "message": "No user currently authenticated.",
   "asctime": "2011-08-22 17:52:54,828",
   "threadName": "MainThread",
   "customer": "my_beloved_customer",
   "trials": 4
}

Great isn’t it? Now you can stream it to your preferred tool and input all these attributes into their analytics. Here is what severity levels by module names coming from dozen of servers can then look like:

Python logging: modules vs severity

b. Operational intelligence

Context can also be used for operational intelligence purposes. So if an e-retailer decides to log whenever a cart is paid, they can attach the user ID, time spent of website, size and price of cart, what was searched, and any other information relevant to understand the user.

But operational intelligence is a big topic and we’ll have other occasions to talk about this.

Wrapping up

I hope this article was useful to you and you learnt some new techniques. You’ll probably realize after only a couple of trials that your log entries can be much more useful than what they are in most places today. Standards, JSON, contextual data and probably a good log management tool can make a big difference on your day-to-day work. On this final note… Enjoy your Python logging!

If you are interested in multi-line handling, check out our I got 99 Problems but Multi-line String Ain’t one post, and for more best practices in log collection have a look at this Logging Best Practices : Collecting Logs article.

Related Posts

Get notified when new content is published