Django sessions: How to include session ID in every log record?

Question

I would like to include session ID (at least portion of it) in every log entry in Django. This would help me group together logs for each user session in case several users are interacting with my Django API at the same time.

I know I can retrieve session ID from Request object (when it exists) but I would have to do so for every logger.info() across the whole framework. Instead it would be much better to have Request somehow available in settings.py so that I can prepend the ID to my formatter's format string inside LOGGING config.

This would ensure that the session ID is included in every log entry and I would not need to think about it in every view or serializer, etc.

But I haven't found a way how to make Request or Session available in settings.py.

EDIT:

To explain further. I have the following signal in place to catch user login and log this event when it happens. I want to add session ID to this message. But I want Django to do it for any message in the system by default - I don't want to fetch the session ID inside the log_user_login function and any other function in my code.

So in the following code I want to fire up logger event, but with no session ID specified.

import logging
from django.dispatch import receiver
from django.contrib.auth.signals import user_logged_in

logger = logging.getLogger(__name__)

@receiver(user_logged_in)
def log_user_login(sender, user, request, **kwargs):
    logger.info(f"User {user.username} logged in.")

I want Django to add session ID then automatically via the configuration in settings.py, for illustration with following code:

def add_session_id(record):
    record.attrs = record.__dict__.keys()
    return True


LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'add_session_id': {
            '()': 'django.utils.log.CallbackFilter',
            'callback': add_session_id,
        }
    },
    'formatters': {
        'file': {
            'format': '%(attrs)s',
        },
    },
}

This would log the following message:

dict_keys(['name', 'msg', 'args', 'levelname', 'levelno', 'pathname', 'filename', 'module', 'exc_info', 'exc_text', 'stack_info', 'lineno', 'funcName', 'created', 'msecs', 'relativeCreated', 'thread', 'threadName', 'processName', 'process', 'attrs', 'message', 'asctime'])

So to me it looks like mentioned record contains neither Request nor Session.

Answer 1

This is my final solution which works for me nicely.

I have written a middleware thread_local.py which extracts username and session ID (if available) from each request and stores these values as local variables for the thread. It allows me to access username and session ID from other parts of the project, including logging.

thread_local.py:

import logging
from threading import local

_thread_locals = local()

logger = logging.getLogger(__name__)


def get_local_thread_value(item):
    """
    Returns value of an item of this current thread.
    """
    return getattr(_thread_locals, item, None)


def list_thread_locals(attrs):
    """
    Returns a line of key:val pairs of current thread locals.
    """
    return str("Current thread locals: " + ', '.join(
        [
            f"{attr}: {str(get_local_thread_value(attr))}"
            for attr in attrs
        ]))


class ThreadLocalMiddleware():
    """
    This middleware, for every request separately, reads important values
    from Request or Session objects and adds them to local thread attributes.
    This makes the values available throughout the project - in views, etc.
    """
    def __init__(self, get_response=None):
        """
        One-time configuration and initialization.
        Called only once at server startup.
        """
        self.get_response = get_response
        self.attrs_to_remove = ['c_user', 'c_session_id', ]

    def _set_user(self, request):
        """Get username from request data and add it to thread."""
        c_user = getattr(request, 'user', None)
        logger.debug(f"_set_user to _thread_locals: {c_user}")
        setattr(_thread_locals, 'c_user', c_user)

    def _set_session_id(self, request):
        """Get session ID from session store and add it to thread."""
        c_session = getattr(request, 'session', {})
        c_session_key = getattr(c_session, 'session_key', None)
        c_session_id = c_session_key[-10:] if c_session_key else None
        logger.debug(f"_set_session_id to _thread_locals: {c_session_id}")
        setattr(_thread_locals, 'c_session_id', c_session_id)

    def _unset_local_attr(self):
        """Remove attributes provided in attr_list from local thread."""
        logger.debug(f"_unset_local_attr")
        for attr in self.attrs_to_remove:
            if hasattr(_thread_locals, attr):
                delattr(_thread_locals, attr)

    def __call__(self, request):
        """
        Called for every request.
        Fetch and store User information into local thread,
        which is then available for logging filter.
        """
        # Code to be executed for each request before
        # the view (and later middlewares) are called.

        self._set_user(request)
        self._set_session_id(request)
        logger.debug(list_thread_locals(self.attrs_to_remove) + " (request)")

        # Forward Request further the satck and wait for Response
        response = self.get_response(request)

        # Code to be executed for each request/response after
        # the view is called.

        # Unset all local thread attributes
        # to ensure they are not kept in next request/response cycle.
        self._unset_local_attr()
        logger.debug(list_thread_locals(self.attrs_to_remove) + " (response)")

        # Let other middlewares execute their response part.
        return response

    def process_exception(self, request, exception):
        """
        In case of exception, delete the local thread attributes,
        and return None so that other middlewares can act too.
        """
        logger.debug('process_exception: exception in thread_local')
        self._unset_local_attr()

Then of course do not forget to register it in settings.py.

LOGGING: For regular logging I have written a custom logging filter:

from core.middleware.thread_local import get_local_thread_value

class CustomLoggingFilter(logging.Filter):
    """
    If logging handler is configured with this filter,
    a log record is updated with User information.
    These attributes can be accessed by any logging formatter,
    as for example: %(c_session_id).

    The filter() method must return True, to ensure the record is logged.
    """
    def filter(self, record):
        record.c_user = get_local_thread_value('c_user')
        record.c_session_id = get_local_thread_value('c_session_id')
        return True

Then the logging section in setting.py can look for example like this (some parts removed for better verbosity):

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'custom_logging_filter': {
            '()': 'core.utils.log.CustomLoggingFilter',
        },
    },
    'formatters': {
        'file': {
            'format': ('%(asctime)s %(c_session_id)-10s '
                       '%(levelname)-8s %(c_user)s '
                       '%(message)s (%(name)s)'),
        },
    },
    'handlers': {
        'base_file': {
            'level': 'INFO',
            'filters': ['custom_logging_filter'],
            'class': 'logging.FileHandler',
            'formatter': 'file',
            'filename': LOG_FILE_BASE,
        },
    },
    'loggers': {
        '': {
            'handlers': ['base_file', ],
            'level': 'DEBUG',
            'propagate': True,
        },
    }
}

It is possible to use the same approach with Django's signals to record these audit events directly in the database, when, for example, the user_logged_in signal triggers custom receiver which calls a function to record new object in audit model.