CODEWITHSUNDEEP
pythonpython-3.xdjangowebgunicorn
Cospel
Cospel

Reputation: 533

Printing username on stdout with Django + Gunicorn Application

Right now my Django + Gunicorn app is printing only this info:

[03.10.2022 19:43:14] INFO [django.request:middleware] GET /analyse/v2/ping - 200

If request is authorized, I would like to show also user (username/email) behind the status code, something like:

[03.10.2022 19:43:14] INFO [django.request:middleware] GET /analyse/v2/ping - 200 - [email protected]

If the request is not authorized then write UNAUTHORIZED:

[03.10.2022 19:43:14] INFO [django.request:middleware] GET /analyse/v2/ping - 200 - UNAUTHORIZED

How can I achieve this with a combination of Django and Gunicorn?

Thank you

Solved by adding this part of code in settings:

def add_username(record):
    try:
        username = record.request.user.username
    except AttributeError:
        username = ""
    record.username = username
    return True

LOGGING = {
    "version": 1,
    "disable_existing_loggers": True,
    "root": {"level": "WARNING", "handlers": ["console"]},
    "formatters": {
        "verbose": {
            "format": "[%(asctime)s] %(levelname)s [%(name)s:%(module)s] [%(username)s] %(message)s",
            "datefmt": "%d.%m.%Y %H:%M:%S",
        },
        "simple": {"format": "%(levelname)s %(message)s"},
    },
    "filters": {
        "add_username": {
            "()": "django.utils.log.CallbackFilter",
            "callback": add_username,
        }
    },
    "handlers": {
        "console": {
            "level": "DEBUG",
            "class": "logging.StreamHandler",
            "formatter": "verbose",
            "filters": ["add_username"],
        },
    ...

Upvotes: 3

Views: 644

Answers (2)

Antoine Pinsard
Antoine Pinsard

Reputation: 35002

It's not clear where this log line comes from. As far as I can see, Django only logs 4xx and 5xx requests to django.request logger. This doesn't look like a gunicorn access log line either. And if you initiated this log line in your own code, you should be able to add the user easily.

So, here are a few generic solutions.

(Option 1) For a gunicorn access log line

You don't have access to Django's request object and thus won't be able to retrieve the user from gunicorn. However, you can work it around by adding the user in the response headers.

yourapp/middleware.py

class UserHeaderMiddleware:

    def __init__(self, get_response):
        self.get_response = get_response

    def __call__(self, request):
        response = self.get_response(request)
        user = request.user
        response['X-User'] = user.email if user.is_authenticated() else 'UNAUTHORIZED'
        return response

yourproject/settings.py

MIDDLEWARE = [
    ...,
    'django.contrib.auth.middleware.AuthenticationMiddleware',
    ...,  # Your custom middleware must be called after authentication
    'yourapp.middleware.UserHeaderMiddleware',
    ...,
]

Then change gunicorn's access_log_format setting to include this header. For instance: '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%({x-user}o)s"'

(Option 2) For django.request logger

If your log line is sent to django.request logger, there is a chance that it provided the request in the extra context.

In that case, you can write a custom Formatter to include the user:

yourapp/logging.py

from logging import Formatter

class RequestFormatter(Formatter):

    def format(self, record):
        request = getattr(record, 'request', None)
        if user := getattr(request, 'user', None):
            record.user = user.email if user.is_authenticated() else 'UNAUTHORIZED'
        else:
            record.user = '-'
        return super().format(record)

yourapp/logging.py

LOGGING = {
    ...,
    'formatters': {
        ...,
        "django.request": {
            "()": "yourapp.logging.RequestFormatter",
            "format": "[{asctime}] {levelname} [{name}] {message} - {status_code} - {user}",
            "style": "{",
        },
    },
    'loggers': {
        ...,
        "django.request": {
            "handlers": ...,
            "level": "INFO",
            "formatter": 'django.request',
       }
       ...,
    },
}

(Option 3) Tell Django to log all requests in django.request

Django only logs 4xx and 5xx requests in django.request. See source code

But we can change this behavior by using a custom WSGI handler.

In yourproject/wsgi.py you should have something like this:

import os
from django.core.wsgi import get_wsgi_application
os.environ.setdefault('DJANGO_SETTINGS_MODULE', 'yourproject.settings')
application = get_wsgi_application()

You can change this to use a custom WSGI handler:

import os
import django
from django.core.wsgi import WSGIHandler
from django.conf import settings
os.environ.setdefault('DJANGO_SETTINGS_MODULE', 'yourproject.settings')


class CustomWSGIHandler(WSGIHandler):
    def get_response(self, request):
        # Note that this is only a copy of BaseHandler.get_response()
        # without the condition on log_response()
        set_urlconf(settings.ROOT_URLCONF)
        response = self._middleware_chain(request)
        response._resource_closers.append(request.close)
        log_response(
            "%s: %s",
            response.reason_phrase,
            request.path,
            response=response,
            request=request,
        )
        return response

django.setup(set_prefix=False)
application = CustomWSGIHandler()

Then, refer to Option 2 to include the user in the formatter.

(Option 4) Create a middleware to add a new log line

If don't have access to this log line to update it and don't have access to the request in the log formatter, you will have to add a new log line manually (and possibly silent the first one to avoid duplicates).

yourapp/middleware.py

import logging

logger = logging.getLogger('django.request')

class LoggingMiddleware:

    def __init__(self, get_response):
        self.get_response = get_response

    def __call__(self, request):
        response = self.get_response(request)
        user_email = request.user.email if request.user.is_authenticated() else 'UNAUTHORIZED'
        logger.info(f"{request.method} {request.path} - {request.status_code} - {user_email}")
        return response

yourproject/settings.py

MIDDLEWARE = [
    ...,
    'django.contrib.auth.middleware.AuthenticationMiddleware',
    ...,  # Your custom middleware must be called after authentication
    'yourapp.middleware.LoggingMiddleware',
    ...,
]

Upvotes: 2

Sam
Sam

Reputation: 96

A custom middleware is how you can achieve this easily. You can do something like the below.

import logging

from loguru import logger  # optional if you are not using it already.

from django.utils import timezone

logger = logging.getLogger('django.request')


class LogRequest:
    def __init__(self, get_response):
        self.get_response = get_response

    def __call__(self, request):
        response = self.get_response(request)

        user = (
            request.user.email
            if request.user.is_authenticated
            else "UNAUTHORIZED"
        )

        logger.info(
            f"[{timezone.now().strftime('%d.%m.%Y %H:%M:%S')}] INFO [myapp.custom_logger] {request.method} {request.path} - {response.status_code} - {user}"
        )

        return response

You can then configure your activate your new middleware by registering it.

MIDDLEWARE = [
    "django.middleware.gzip.GZipMiddleware",
    "django.middleware.security.SecurityMiddleware",
    ...
    "myapp.middleware.LogRequest",
]

This produces an output like the below.

[25.11.2022 15:57:37] INFO [myapp.custom_logger] GET /analyse/v2/ping - 200 - [email protected]

Upvotes: 1

Related Questions