How to enhance Django REST framework exception logging

If you’re using Django and you need an API the first thing that comes to mind is plugging in DRF.

And you’re not alone. In the 2022 Django Developer Survey¹ 60% of respondents listed djangorestframework as “one of their favorite third-party Django packages”.

This reputation is well-deserved as DRF makes writing APIs a breeze. One way it does that is by having model serializers implement the default validation needs without you needing to write a single line of code. Instead you just configure things as in the docs. Convention over configuration for the win.

Use Case

Whenever a model serialzier raises a validation error DRF returns a response with HTTP status 400.

By default Django provides loggers as django.request to log request events. This is explained in detail in the excellent Django docs on logging.

The configuration used for django.request logger in the below examples is:

LOGGING = {
    "formatters": {
        "default": {
            "format": "[%(asctime)s] [%(levelname)s] [%(name)s] %(message)s",
        },
    },
    "filters": {},
    "handlers": {
        "error_console": {
            "level": "WARNING",
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stderr",
            "formatter": "default",
        },
    },
    "loggers": {
        ...
        "django.request": {
            "handlers": ["error_console"],
            "level": "INFO",
            "propagate": False,
        },
        ...
    },
}

This default configuration results in this error being logged when on HTTP 400 response:

[2023-07-23 14:38:38,738] [WARNING] [django.request] Bad Request: /api/profiles/

To generate the above I made an HTTP POST request with an invalid date_of_birth when creating a profile.

This does not log any additional context. Such as the payload that resulted in the Bad Request HTTP 400.

Customising exception handing in DRF

The hook DRF provides comes in the form of EXCEPTION_HANDLER setting under REST_FRAMEWORK setting in your project settings.py:

REST_FRAMEWORK = {
    'EXCEPTION_HANDLER': 'path.to.handler.function'
}

From the docs:

You can implement custom exception handling by creating a handler function that converts exceptions raised in your API views into response objects. This allows you to control the style of error responses used by your API.

While we do not need to convert exceptions raised, we can use this hook to do custom logging.

Here’s the initial implementation:

# myapp/exceptions.py
import logging

from rest_framework import status
from rest_framework.exceptions import APIException
from rest_framework.response import Response
from rest_framework.views import exception_handler

logger = logging.getLogger(__name__)


def custom_exception_handler(exception: APIException, context: dict) -> Response:
    response = exception_handler(exception, context)

    if response and response.status_code == status.HTTP_400_BAD_REQUEST:
        logger.warning("Bad Request: %s", context["request"].path)

    return response

And remember to set the settings configuration accordingly:

REST_FRAMEWORK = {
    'EXCEPTION_HANDLER': 'myapp.exceptions.custom_exception_handler'
}

Note the condition:

if response and response.status_code == status.HTTP_400_BAD_REQUEST:
    ...

Why check response object with if response?

The reason is the default rest_framework.views.exception_handler can return None in case of an exception that results in HTTP 500. This can happen, for instance, in case of database-level IntegrityError. An integrity constraint violation is caused by a variety of reasons, a common case is trying to insert a duplicate value in a unique column.

So how does the logging look with the custom exception handler? We see both our logger under myapp.exceptions and the default one by django.request.

[2023-07-23 14:43:20,380] [WARNING] [myapp.exceptions] Bad Request: /api/profiles/
[2023-07-23 14:43:20,380] [WARNING] [django.request] Bad Request: /api/profiles/

Success! Or is it? Shouldn’t we log the same event only once?

Avoiding duplicate logging

I scoured the docs but I didn’t find much.

So I ended up diving into Django’s codebase to see which code writes the django.request log. The code is in django.utils.log.log_response function². The function’s docstring reads:

Log errors based on HttpResponse status.

Log 5xx responses as errors and 4xx responses as warnings (unless a level is given as a keyword argument). The HttpResponse status_code and the request are passed to the logger’s extra parameter.

We’re in the right place, yay!

The function’s first lines:

# Check if the response has already been logged. Multiple requests to log
# the same response can be received in some cases, e.g., when the
# response is the result of an exception and is logged when the exception
# is caught, to record the exception.
if getattr(response, "_has_been_logged", False):
    return

Seems exactly what I was looking for in the docs. Added one line to the function:

def custom_exception_handler(exception: APIException, context: dict) -> Response:
    response = exception_handler(exception, context)

    if response and response.status_code == status.HTTP_400_BAD_REQUEST:
        logger.warning("Bad Request: %s", context["request"].path)
        setattr(response, "_has_been_logged", True)  # <- THIS

    return response

And voila, duplicate logging eliminated:

[2023-07-23 14:44:47,441] [WARNING] [myapp.exceptions] Bad Request: /api/profiles/

Customising logging

Using custom logging we can take advantage of specific features used by our log handling tool.

For instance using Google Cloud Logging a couple of features come in handy for this use case:

1. Automatic metadata detection, for example of the request object, and
2. Logging JSON payloads.

The code with these enhancements:

def custom_exception_handler(exception: APIException, context: dict) -> Response:
    response = exception_handler(exception, context)

    if response and response.status_code == status.HTTP_400_BAD_REQUEST:
        request_data = {"request_data": context["request"].data}
        logger.warning(
            "Bad Request: %s",
            context["request"].path,
            extra={
                "status_code": response.status_code,
                "http_request": context["request"],
                "json_fields": request_data,
            },
        )
        # prevent repsonse from being logged again by "django.request" logger
        setattr(response, "_has_been_logged", True)

    return response

Caveats

Note that depending on your logging provider, logging a too large HTTP request body might either fail or cause a nasty billing surprise. So keep what you log in mind. It’s good to think of approaches to avoid such situations. For example setting a maximum payload size when logging the request payload.

References

I tried not to reinvent the wheel. And I’ve encountered django-request-logging package:

Plug django-request-logging into your Django project and you will have intuitive and color coded request/response payload logging, for both web requests and API requests.

It does what I was looking for. But it also does a lot more. That’s why I decided not to use it. It does however implement setting a maximum payload size when logging the request payload. Your mileage might vary.

Footnotes