Microservices Communication | SentinelOne

Getting Started Quickly With Django Logging

Django is one of the most popular Python web application frameworks, used by numerous organizations. Since it employs the built-in Python logging facility, logging in Django is a snap.

Still, there are a few specific Django configuration options to keep in mind. In this article, we’ll

  • create a Python virtual environment,
  • set up a small Django project to work with,
  • write a basic logging example,
  • configure the Django logger, and
  • explore the Django logging extensions.

If you want to skip writing code, you can find all of the code in this article over on GitHub.

Also, note that this article won’t go into details on the specifics of Python logging. If you want a primer on those, check out this previous post, Get Started Quickly With Python Logging, which covers the basics.

Now ready, set, log!

Create a Python Virtual Environment

Python virtual environments are a great way to keep your systemwide Python environment clean. They isolate your project dependencies and keep the Python system installation free of cruft and dependency issues.

Since we’ll be using Python 3 in this article, before creating the Python virtual environment double-check to make sure you’re running a recent version:

$ python3 --version
Python 3.7.0

Next, create a directory to keep our project in:

$ mkdir django-logging && cd $_

All right. Before we move onto the next section, let’s create and activate our new virtual environment:

django-logging$ python3 -m virtualenv env 
Using base prefix '/usr/local/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7' 
New python executable in /Users/casey/projects/django-logging/env/bin/python3.7 
Also creating executable in /Users/casey/projects/django-logging/env/bin/python 
Installing setuptools, pip, wheel... done.
django-logging$ source env/bin/activate
(env) django-logging$

Now everything is good to go to install Django.

Install Django

Within the virtual environment, installing Django is as easy as 1, 2, pip install Django:

(env) django-logging$ pip install Django
Collecting Django
  Using cached https://files.pythonhosted.org/packages/d1/e5/2676be45ea49cfd09a663f289376b3888accd57ff06c953297bfdee1fb08/Django-2.1.3-py3-none-any.whl
Collecting pytz (from Django)
  Using cached https://files.pythonhosted.org/packages/f8/0e/2365ddc010afb3d79147f1dd544e5ee24bf4ece58ab99b16fbb465ce6dc0/pytz-2018.7-py2.py3-none-any.whl
Installing collected packages: pytz, Django
Successfully installed Django-2.1.3 pytz-2018.7

Quickly verify the installation by checking the version of Django:

(env) django-logging$ python -m django --version
2.1.3

Great! Now let’s move on to creating a simple hello world application.

Create a Simple Application

For this article this project isn’t going to be anything fancy—just a simple web page handler that will be the logging test bed. Before creating our module it needs a name, which will be app. (I know, that’s not very clever, but it’s late and I’m heading out for vacation soon.)

The django-admin command will create an initial application skeleton for us:

(env) django-logging$ django-admin startproject app

There won’t be any output, but in your directory you should see a new app folder:

(env) django-logging$ ls
env	app

As one final step to make sure everything is up and running, fire up the built-in Django web server:

(env) django-logging$ cd app
(env) app$ python manage.py runserver
Performing system checks...

System check identified no issues (0 silenced).

You have 15 unapplied migration(s). Your project may not work properly until you apply the migrations for app(s): admin, auth, contenttypes, sessions.
Run 'python manage.py migrate' to apply them.

November 29, 2018 - 00:58:04
Django version 2.1.3, using settings 'app.settings'
Starting development server at http://127.0.0.1:8000/
Quit the server with CONTROL-C.

See that scary message about the 15 unapplied migrations? Just ignore that. Open up a browser and point it at http://localhost:8000 and you should see the default Django web page:

Add a New Django Module

Now that we’ve got all our scaffolding in place, let’s create a module named hello. Once again, Django provides another handy script, manage.py, that takes care of a bit of scaffolding:

(env) django-logging$ python manage.py startapp hello

This command will create a new folder named hello along with a few additional Python files. Replace the contents of hello/views.py with the following:

from django.http import HttpResponse

def index(request):
    return HttpResponse("Hello logging world.")

This creates our initial view, but we still need to let Django know about it. Create a new file in hello/urls.py and add the following to it:

from django.urls import path

from . import views

urlpatterns = [
    path('', views.index, name='index'),
]

This hooks up our view to the base URL path (the empty string). Now all we need to do is hook this into the app/urls.py file so Django knows how to route everything. Open app/urls.py and replace its contents with the following:

from django.contrib import admin
from django.urls import include, path

urlpatterns = [
    path('', include('hello.urls'))
]

Next, start the web server as we did before:

(env) app$ python manage.py runserver

Instead of the default Django welcome screen, we’ll see our lackluster, but useful, view:

Whew. Thanks for sticking with it. Now that we have all that out of the way, let’s look at how to utilize logging within the Django application.

First Steps With Logging

Since we covered Python logging in the Get Started Quickly With Python Logging article, we won’t rehash the same information here except to provide clarity around playing nicely with the Django framework. If you’re new to Python or want a quick refresher, go ahead and read through that article first.

The simplest possible logging we can do is just to import the Python logging module and start logging. Begin by updating the app/views.py file with the following code:

import logging

from django.http import HttpResponse

# This retrieves a Python logging instance (or creates it)
logger = logging.getLogger(__name__)

def index(request):
    # Send the Test!! log message to standard out
    logger.error("Test!!")
    return HttpResponse("Hello logging world.")

Here we’re importing the logging module and then using the getLogger method to get a logging instance we can use. In the index method, we emit our log message using the logger.error method. Restart the web server and refresh the page to see our message in the console window:

(env) app$ python manage.py runserver
Performing system checks...

System check identified no issues (0 silenced).

You have 15 unapplied migration(s). Your project may not work properly until you apply the migrations for app(s): admin, auth, contenttypes, sessions.
Run 'python manage.py migrate' to apply them.

November 29, 2018 - 02:11:30
Django version 2.1.3, using settings 'app.settings'
Starting development server at http://127.0.0.1:8000/
Quit the server with CONTROL-C.
Test!!
[29/Nov/2018 02:11:35] "GET / HTTP/1.1" 200 20
Not Found: /favicon.ico
[29/Nov/2018 02:11:35] "GET /favicon.ico HTTP/1.1" 404 2024

Configure the Logger

By default, Django uses the dictConfig format for configuring logging handlers, filters, and formatting. These settings are set through the LOGGING dictionary, which is merged with the Django default logging configuration. Let’s look at a simple logging configuration and then walk through it.

import logging

logging.config.dictConfig({
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'console': {
            'format': '%(name)-12s %(levelname)-8s %(message)s'
        },
        'file': {
            'format': '%(asctime)s %(name)-12s %(levelname)-8s %(message)s'
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'console'
        },
        'file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'formatter': 'file',
            'filename': '/tmp/debug.log'
        }
    },
    'loggers': {
        '': {
            'level': 'DEBUG',
            'handlers': ['console', 'file']
        }
    }
})

OK, that’s a lot. Let’s break it down.

version

The dictConfig schema doesn’t require a version, but setting it ensures backward compatibility. Currently, the only valid value here is 1.

disable_existing_loggers

This setting disables existing loggers. The default value is False, but it doesn’t hurt to be explicit. When setting this to True, define additional loggers. Otherwise, messages may be lost.

formatters

This section defines what our log statements will look like. We aren’t going to cover all the possible formatting options here, but this article describes everything that’s supported. Let’s take a look at the console log format:

%(name)-12s %(levelname)-8s %(message)s

Here’s what’s going on:

  • %(name) – this is the package name that emits the log message
  • %(levelname) – the log level of the message (ERROR, WARNING, INFO, etc.)
  • %(message) – this is the actual log message

The -12s and the -8s control spacing between the different format specifications. An example message in this format will look like the following:

hello.views  ERROR    Test!!

You’ll notice the file formatter includes an additional specifier, the %(asctime). This adds a timestamp to each message sent through the file handler. As an example, the message from our defined debug.log will resemble this:

2018-11-29 14:36:58,739 hello.views  ERROR    Test!!

handlers

This section defines how to handle log messages. We can send messages to the console, files, or even sockets! All the default handlers are in the Python docs here. This configuration defines separate handlers: one for console messages and another for messages sent to the file. In addition, for the file handler we specify the handler class, the filename to log to, and the log level. This handler also specifies which formatter to use.

loggers

This last section is where we tie it all together and define our loggers, including how to handle the root logger (represented by the empty string) messages. We also set the logging level to DEBUG and define two handlers, one to the console and one to the file.

Let’s update the configuration now and take it for a spin.

Update and Test the New Configuration

Update the app/views.py to include the above logging configuration. It should look like this:

import logging

from django.http import HttpResponse

logging.config.dictConfig({
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'console': {
            'format': '%(name)-12s %(levelname)-8s %(message)s'
        },
        'file': {
            'format': '%(asctime)s %(name)-12s %(levelname)-8s %(message)s'
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'console'
        },
        'file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'formatter': 'file',
            'filename': '/tmp/debug.log'
        }
    },
    'loggers': {
        '': {
            'level': 'DEBUG',
            'handlers': ['console', 'file']
        }
    }
})

# This retrieves a Python logging instance (or creates it)
logger = logging.getLogger(__name__)

def index(request):
    # Send the Test!! log message to standard out
    logger.error("Test!!")
    return HttpResponse("Hello logging world.")

Running that as before and refreshing the browser, the console log message now includes the additional information from our format string:

$ python manage.py runserver
...
November 29, 2018 - 14:36:56
Django version 2.1.3, using settings 'app.settings'
Starting development server at http://127.0.0.1:8000/
Quit the server with CONTROL-C.
hello.views  ERROR    Test!!

The log file will contain the same message and format, but with the addition of the timestamp:

(env) app$ cat /tmp/debug.log 
2018-11-29 14:36:58,739 hello.views  ERROR    Test!!

This is enough to start incorporating logging in any Django project. However, we have one more topic to cover and it’s the logging extensions that Django provides.

Tour the Django Logging Extensions

In a web server environment we often have routine information we need to log. Django provides a few logging extensions to cover these use cases.

django

This is a catch-all logger for messages in the django hierarchy. Messages aren’t posted using this logger name since one of the following loggers will be used.

django.request

This logger handles the logging of HTTP requests and will raise exceptions for certain status codes. All HTTP 5xx error codes will raise ERROR messages. Likewise, HTTP 4xx codes will appear as WARNING messages.

django.server

When running the server using the runserver command (which we’ve been doing), this will log messages related to the handling of those requests just like the django.request logger—except that all other messages are logged at the INFO level. These are messages that do not trigger an HTTP status code of 5xx or 4xx.

django.template

No matter how often I’ve worked with Django templates, I’ve never put one together without errors the first time. The django.template logger handles errors related to the rendering of templates. Missing context variables will appear in the log as DEBUG messages.

django.db.backends

This logger handles any messages from the interaction of the code with the database. All application-level SQL statements will appear at the DEBUG level. As this can get quite noisy, debug logging needs to be enabled by changing settings.DEBUG to True.

django.security.*

Django provides handlers for security-related errors. In particular, the logger will receive any messages that result from a SuspiciousOperation error. Django defines subclasses for each kind of security error such as DisallowedHost or InvalidSessionKey. The rest of the subclasses of SuspiciousOperation can be found here.

A word of caution. If the django.security logger handles a message, it will not be sent through the django.request logger. So don’t ignore messages from the django.security.* loggers!

django.security.csrf

This logger doesn’t inherit from the SuspiciousOperation logger that the other security handlers extend. This handles any exceptions that occur due to Cross-Site Request Forgery (CSRF) attacks.

As one final example, let’s log messages from the django.request extension. This is done by adding the logger to the logging section of the configuration like so:

logging.config.dictConfig({
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'console': {
            'format': '%(name)-12s %(levelname)-8s %(message)s'
        },
        'file': {
            'format': '%(asctime)s %(name)-12s %(levelname)-8s %(message)s'
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'console'
        },
        'file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'formatter': 'file',
            'filename': '/tmp/debug.log'
        }
    },
    'loggers': {
        '': {
            'level': 'DEBUG',
            'handlers': ['console', 'file']
        },
        'django.request': {
            'level': 'DEBUG',
            'handlers': ['console', 'file']
        }
    }
})

This will log request messages like the following:

2018-11-29 16:24:02,167 django.request WARNING  Not Found: /favicon.ico

Feel free to experiment, and don’t forget to log the django.security.* messages!

You’ve Got This!

That was a lot of information, so let’s recap:

  • Django uses the standard Python logging facilities.
  • Logging settings are set through the logging.dictConfig dictionary.
  • Django provides a few logging extensions for handling common web server issues.

If you need to delve further, read up on the Python logging facility as well as the Django logging specifics. Also, a reminder that all the code used in this article can be found on GitHub.

Until next time, happy logging!

This post was written by Casey Dunham. Casey, who recently launched his own security business, is known for his unique approaches to all areas of application security, stemming from his 10+ year career as a professional software developer. His strengths include secure SDLC development consulting; threat modeling; developer training; and auditing web, mobile, and desktop applications for security flaws.