Django logging custom attributes in formatter

Question

How can Django use logging to log using custom attributes in the formatter? I'm thinking of logging the logged in username for example.

In the settings.py script, the LOGGING variable is defined:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse'
        },
    },
    'formatters' : {
        'info_format' : {
            'format' : '%(asctime)s %(levelname)s - %(message)s',
        },
    }
}

I wish to use a format, something like:

'format' : '%(asctime).19s %(levelname)s - %(username)s: %(message)s'

Where username would be the currently logged in user. Maybe any other kind of session's variables may be added here.

A workaround here is to use the extra parameter on the logger methods, which receives a dictionary with the keys as the strings I want to use on the format string:

logger.info(message, extra={'username' : request.user.username})

Another (ugly) workaround would be to build the message attribute to include the things that are not part of the default attributes that logging formatters have.

message = request.user.username + " - " + message
logger.info(message)

But, is there a way to set up the format string with certain attributes and make Django give them automatically to the logging API? If %(username)s for example, the request.user.username, of any others perhaps...

Answer 1

You can use a filter to add your custom attribute. For example :

def add_my_custom_attribute(record):
    record.myAttribute = 'myValue'
    record.username = record.request.user.username 
    return True

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        ...
        'add_my_custom_attribute': {
            '()': 'django.utils.log.CallbackFilter',
            'callback': add_my_custom_attribute,
        }
    },
    'handlers': {
        ...
        'django.server': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'filters': ['add_my_custom_attribute'],
            'formatter': 'django.server',
        },            
    },
    ...
}

---

By installing a filter, you can process each log record and decide whether it should be passed from logger to handler.

The filter get the log record which contains all the details of log (i.e : time, severity, request, status code).

The attributes of the record are used by the formatter to format it to string message. If you add your custom attributes to that record - they will also be available to the formatter.

Answer 2

The extra keyword is not a workaround. That's the most eloquent way of writing customized formatters, unless you are writing a custom logging altogether.

format: '%(asctime).19s %(levelname)s - %(username)s: %(message)s'
logging.basicConfig(format=format)
logger.info(message, extra={'username' : request.user.username})

Some note from the documentation (**kwars for Django logger):

The keys in the dictionary passed in extra should not clash with the keys used by the logging system.

If the strings expected by the Formatter are missing, the message will not be logged.

This feature is intended for use in specialized circumstances, and not always.

Answer 3

I will provide one of many possible complete answers to this question:

How can Django use logging to log using custom attributes in the formatter? I'm thinking of logging the logged in username for example.

Other answers touched on the way to add extra contextual info through python's logging utilities. The method of using filters to attach additional information to the log record is ideal, and best described in the docs:

https://docs.python.org/3/howto/logging-cookbook.html#using-filters-to-impart-contextual-information

This still does not tell us how to get the user from the request in a universal way. The following library does this:

https://github.com/ninemoreminutes/django-crum

Thus, combine the two, and you will have a complete answer to the question that has been asked.

import logging
from crum import get_current_user

class ContextFilter(logging.Filter):
    """
    This is a filter injects the Django user
    """

    def filter(self, record):

        record.user = get_current_user()
        return True

if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG,
                        format='User: %(user)-8s %(message)s')
    a1 = logging.getLogger('a.b.c')

    f = ContextFilter()
    a1.addFilter(f)
    a1.debug('A debug message')

This will need to happen within a Django request-response cycle with the CRUM library properly installed.