Looking for an easy-to-use web framework that provides high-level building blocks to go from concept to production quickly? One popular choice is Django, a Python web development framework originally created at World Online, a newspaper web company for rapidly building and launching websites to support news stories.
Popular websites such as Instagram, Pinterest, and Mozilla use Django to serve millions of users a year. In other words, Django scales well. Really well.
And a key piece of ensuring that large-scale web applications keep working is monitoring their health with logging. With well-implemented logging, you can peek inside your apps and understand exactly how they’re behaving, which is especially useful when you’re troubleshooting production code at three in the morning.
Before I get to the logging gotchas you will want to avoid, let’s walk through some of the basics of setting up logging in Python and how to get started using Django logging with SolarWinds® Papertrail™. I will share some best practices so that you can use your logs to understand exactly what your app is doing.
The Fundamentals of Logging in Python
Logging in Python uses the built-in logging module, which contains four major components: loggers, handlers, filters, and formatters. This logging module lets you send messages to its loggers using one of the debug, info, warning, critical, or error functions. Each function creates a log record with a corresponding log level of the same name, with the log level’s priority rising from DEBUG (lowest) to ERROR (highest). The debug function creates messages with the DEBUG log level, for example. There are two additional logger functions for emitting log messages: log and exception. log allows you to specify the message’s exact log level, and by using exception inside exception handlers, you can log messages at the ERROR level and include the exception info in the log message.
Each Python logger has a configured minimum log level for the messages it accepts. For example, if a logger log level is INFO, the logger ignores any messages sent by calling its debug function.
Loggers send messages—known as log records—to one or more handlers responsible for routing messages to their final destination, such as the console, a file, or a network socket. Handlers also have a configured log level they will accept, and will ignore any messages they receive that have a lower level. A logger can also have more than one handler, letting you send a single message to multiple destinations, or choose a particular destination based on the attributes of the log record. For example, you can send DEBUG messages to a log file and CRITICAL messages via email to the operations team.
Filters provide another (optional) mechanism beyond log levels for controlling which messages are passed between loggers and handlers. For example, you can install filters to ignore log messages sent from calls inside third-party code by filtering on the LogRecord.pathname and LogRecord.filename attributes, or redirect a message to a different handler if it contains an exception in LogRecord.exc_info.
And finally, once a message arrives at its destination, it’s processed using a formatter. Formatters are Python strings that control the way that log message text is rendered.
The above breakdown is applicable to every Python app. But, in the spirit that it was created, Django also provides additional logging infrastructure to help you build apps more quickly without having to worry about every little logging detail.
Logging in Your Django App
By default, the Django web framework uses a LOGGING object to configure logging. LOGGING uses the dictConfig format—a dictionary of key/value pairs—to create the necessary Python loggers, handlers, filters, and formatters.
Django also provides some extra loggers that it uses to record web-app-specific information, such as HTTP requests (django.request) and interactions with the database (django.db.backends). These additional loggers are useful for understanding the inner workings of the Django framework, and it’s through the LOGGING dictConfig, and its handlers value, that you tell Django where loggers should send log records.
Here’s an example LOGGING configuration that directs all log messages sent to the django logger, at or above the INFO level, to a file:
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'handlers': {
'file': {
'level': 'INFO',
'class': 'logging.FileHandler',
'Filename': '/code/myapp/logs/info.log',
},
'loggers': {
'django': {
'handlers': ['file'],
'level': 'INFO',
'propagate': True,
},
},
}The following command shows the messages written to the log file by Django when a user accesses the non-existent /missing page:
$ cat logs/info.log
Not Found: /missing
"GET /missing HTTP/1.1" 404 77You can also add your own loggers to your app. The logging.getLogger() function returns a logger object you can send messages to. Here’s an updated LOGGING config example that sends all messages at or above CRITICAL to the console and to the same log file used by the Django loggers.
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'handlers': {
'file': {
'level': 'INFO',
'class': 'logging.FileHandler',
'filename': '/code/myapp/logs/info.log',
},
'console': {
'level': 'DEBUG',
'class': 'logging.StreamHandler',
},
},
'loggers': {
'django': {
'handlers': ['file'],
'level': 'INFO',
'propagate': True,
},
'app-logger': {
'handlers': ['file', 'console'],
'level': 'CRITICAL',
'propagate': True,
},
},
}This logger is used inside of our app like so:
import logging
def appError():
appLogger = logging.getLogger('app-logger')
appLogger.critical("A critical error occurred")Notice how the console handler is configured to accept any message at or above the DEBUG level, but the logger only accepts INFO messages or higher. This is a good example of how loggers and handlers are loosely coupled and can be configured independently.
Sending Logs to Papertrail
There are two ways to send logs to your Papertrail account. You can write your messages to a log file and send it to Papertrail using remote syslog2, or you can use Python’s SysLogHandler handler class. Transmitting log files with remote_syslog2 is the least flexible technique, but also the simplest. The example LOGGING config above shows how to write to a log file from your Django app. Sending that file to your Papertrail account is covered in the Papertrail Knowledge Base.
Using Python’s SysLogHandler handler class offers far more control over exactly how you send your logs to Papertrail. This method is the best choice if you want to store the logic for sending logs to Papertrail in the app code itself. To use the SysLogHandler class, you need to add new handlers and formatters entries to LOGGING and update the handlers list for the django and app-logger loggers.
LOGGING = {
...
'handlers': {
...
'SysLog': {
'level': 'INFO',
'class': 'logging.handlers.SysLogHandler',
'formatter': 'simple',
'address': ('logsN.papertrailapp.com', XXXXX)
},
…
'formatters': {
'simple': {
'format': '%(asctime)s HOSTNAME APP_NAME: %(message)s',
'datefmt': '%Y-%m-%dT%H:%M:%S',
},
},
'loggers': {
'django': {
'handlers': ['file', 'SysLog'],
'level': 'INFO',
'propagate': True,
},
'app-logger': {
'handlers': ['file', 'console', 'SysLog'],
'level': 'CRITICAL',
'propagate': True,
},
},
}The simple formatter added above renders log text in a syslog-like format. Here’s an example of the output:
2019-03-28T15:02:59 HOSTNAME APP_NAME: A critical error occurredTo get this to work, you need to replace the address entry with the log destination from your Papertrail account. You should also consider updating the HOSTNAME and APP_NAME strings, either by hard-coding the right value in the LOGGING config with socket.gethostname() or by creating a custom logging filter to write a log record hostname attribute.
And that’s everything you need to know to get started using Papertrail with Django logging. But before you can benefit from Papertrail’s easy searching and filtering, live tailing, and customizable alerts, there are a few Django logging gotchas to mention.
Gotcha 1 – You Can’t Send Multiline Messages
The syslog format requires all messages to be a single line. If you need to send log data that spans multiple lines—a stack trace from a Python exception is a good example—then you need to transmit each line in a separate syslog message.
Here’s an example that shows how to split a Python exception message and send each line to the logger individually:
import logging
appLogger = logging.getLogger('app-logger')
tb = ""
try:
a = 1/0
except:
tb = traceback.format_exc()
lines = tb.split('\n')
for l in lines:
appLogger.info(l)Gotcha 2 – Tracking Logger Names is Hard
If you pass the __name__ variable to getLogger(), you have a handy way of creating separate logger objects for each level in your module path. getLogger() takes a string as its only argument and returns the existing Logger object with that name, or instantiates a new one if it doesn’t already exist.
For example, if your module has the path project/core/module, Python’s logging infrastructure will map that to project.core.module, which creates three separate loggers: project, project.core, and project.core.module. These loggers form a logging hierarchy and each of them can be configured independently.
Plus, using __name__ means you don’t have to remember the name of every logger.
Gotcha 3 – Django Disables All Loggers by Default
Even though Django comes with extra loggers, both those and the standard Python loggers are disabled by default, which means they’re still available but will ignore any log messages they receive. It’s actually slightly worse than that, though, because the child loggers won’t propagate messages up the hierarchy to their parent loggers either. This behavior has caused all kinds of confusion for developers in the past and eventually resulted in updates to the official Django documentation to clarify things.
You can enable all loggers by setting disable_existing_loggers to False in the LOGGING dictConfig. Alternatively, if you want to handle setting up logging yourself, you can disable Django’s automatic logging configuration and handle logging yourself by setting LOGGING_CONFIG to None.
Gotcha 4 – Too Many Logging Calls Hurts Performance
Your Django app making several calls to the logging module can hurt performance, even if the log record is ultimately ignored, such as when the log level has no handler willing to receive it. That’s because all arguments that you pass to logger functions are evaluated at the time the function is called.
You can optimize your logging by using the Python logging module’s isEnabledFor() function, which takes a log level as its only parameter and returns False if the logger would ignore the call, and True if it would accept the message and create a log record.
Here’s an example of using isEnabledFor() to detect whether DEBUG messages are ignored by the appLogger logger:
if appLogger.isEnabledFor(logging.DEBUG):
appLogger.debug("This is a debug message: %s", expensive_arg())Conclusion
Django was created with speed in mind, but you can’t just jump into writing your app without thinking about logging and monitoring. A well-implemented logging setup is essential for building reliable large-scale web apps. Thanks to Django’s strong foundation, it couldn’t be easier for you to send your app’s valuable logs to SolarWinds® Papertrail™. Once there, you can inspect them to truly understand how your app works and troubleshoot issues when they crop up.