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