Logging In Django

Logging is one of the most beautiful feature in django giving a developer flexibility to log the requests as per the severity level. We often need to keep records of the failures, faults and resource access.

Consider a simple use case where you need to keep logs of request and the IP address from which those request are made. In this post i’ll be creating a simple logger which keeps track of the request with the time at which request is made and the IP associated with it. But before jumping into those things let’s get insight of the different logging component.

Logging Components:

i. Logger

• Entry point into the logging system.
• Have to configure a logging level.

DEBUG: Low level system information for debugging purposes
INFO: General system information
WARNING: Information describing a minor problem that has occurred.
ERROR: Information describing a major problem that has occurred.
CRITICAL: Information describing a critical problem that has occurred.

ii. Handlers

• Engine that determines what happens to each message in a logger
• Describes a particular logging behavior, such as writing a message to the screen, to a file, or to a network socket
• Also have log level that keeps track of weather to handle such log or not.
• If the log level of a log record doesn’t meet or exceed the level of the handler, the handler will ignore the message.

A logger can have multiple handlers, and each handler can have a different log level. In this way, it is possible to provide different forms of notification depending on the importance of a message.

For example, you could install one handler that forwards ERROR and CRITICAL messages to a paging service, while a second handler logs all messages (including ERROR and CRITICAL messages) to a file for later analysis.

iii. Filters:

• Used to provide additional control over which log records are passed from logger to handlers.
• By default, any log message that meets log level requirements will be handled.
• Can be installed on loggers or on handlers; multiple filters can be used in a chain to perform multiple filtering actions.

Filters can also be used to modify the logging record prior to being emitted.
For example, you could write a filter that downgrades ERROR log records to WARNING records if a particular set of criteria are met.

iv. Formatters
- Formatters describe the exact format of that text.

Logging Definition

LOGGING = {
  'version': 1, # is the only one supported
  'disable_existing_loggers': False, # disable default logger ?
  'filters': {},
  'formatters': {},
  'handlers': {},
  'loggres': {}
}

Implementing Our Logger:

We’ll be creating a simple logger that keeps records of time, IP in a log file.

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'add_extra_params': {
            '()': 'django.utils.log.CallbackFilter',
            'callback': get_extra_params,
        }
    },
    'formatters': {
        'request_formatter': {
            'format': "[{request.method} request from IP: {ip} at {time} with severity {levelname} ] :: {message}\n",
            'style': '{'
        }
    },
    'handlers': {
        'log_to_file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'filename': './logs/debug.log',
            'formatter': 'request_formatter',
            'filters': ['add_extra_params']
        },
    },
    'loggers': {
        'django.request': {
            'handlers': ['log_to_file'],
            'level': 'DEBUG',
        },
    },
}

Understanding The Flow:

As described previously we’ve four components interacting with each other to dump our logs into the file.

1. Logger

'loggers': {
        'django.request': {
            'handlers': ['log_to_file'], # takes a list of handlers
            'level': 'DEBUG',
        },
}

For the mentioned use case we can use django.request logging extension which provides the request data which we can format later for flexibility. Other inbuilt extensions can be found Here. They have their own use case.

Similarly we’ve defined a handler which handles the logging i.e though system has caught the logging entry point now we need to tell the handler, how the system is going to handle the logs generated. So we’ve defined a handler named log_to_file. Handler dictionary takes the list of the handlers we define in the handlers dict.

2. Handlers

Handlers as the name suggests takes the in memory logs data generated by the logger and further handles what to do next.

'handlers': {
        'log_to_file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler', # log to file
            'filename': './logs/debug.log',
            'formatter': 'request_formatter',
            'filters': ['add_extra_params']
        },
    },

So we’ve a defined a handler which takes the logs and writes those to the file using logging.FileHandler in the class key of the dict. This is the predefined class.

Similarly, we’ve to provide the path of the file where the output is to be appended. For that purpose we used filename key.

Formatter, as told earlier tells how we want to format the output generated. we used a custom formatter named request_formatter which we’ll cover soon.

Finally we’ve a filter named add_extra_params which adds the extra parameters needed for the formatter. For our use case, we cannot directly extract the IP address from the log data. We need to hook into the data (instance of record) we catch in the filter and modify as per the flexibility.

3. Filters

Filter has variety of use case. We can catch multiple log records and generate some custom data that can be passed to the filter by summing on the results from as many logger we catch there.

But our current use case is not that complex. So we used the filter so that we can pass extra parameters that can be extracted from the request.

def get_extra_params(record):
    """Returns extra params for the logger filter that can be accessed on formatter"""
    from datetime import datetime
    record.ip = record.request.META.get('REMOTE_ADDR') # ip
    record.time = datetime.strftime(datetime.now(), '%Y-%m-%d %H:%M %p') # formatted date and time
    return True

'filters': {
        'add_extra_params': {
            '()': 'django.utils.log.CallbackFilter',
            'callback': get_extra_params,
        }
},

We’ve defined a custom call back filter which hooks into the record generated by logs. To enable such flexibility we used ‘()’: ‘django.utils.log.CallbackFilter’.

We’ve a callback parameter pointed to the callable(function) which adds two parameter into the record (ip & time) which can be accessed on our formatter.