mirrors_areski/django-structlog

django-structlog

django-structlog is a structured logging integration for Django project using structlog

Logging will then produce additional cohesive metadata on each logs that makes it easier to track events or incidents.

Additional Popular Integrations

Django REST framework

Django REST framework is supported by default. But when using it with rest_framework.authentication.TokenAuthentication (or other DRF authentications) user_id will be only be in request_finished and request_failed instead of each logs.

See #37 for details.

Celery

Celery's task logging requires additional configurations, see documentation for details.

Logging comparison

Standard logging:

>>> import logging
>>> logger = logging.get_logger(__name__)
>>> logger.info("An error occurred")

An error occurred

Well... ok

With django-structlog and flat_line:

>>> import structlog
>>> logger = structlog.get_logger(__name__)
>>> logger.info("an_error_occurred", bar="Buz")

timestamp='2019-04-13T19:39:31.089925Z' level='info' event='an_error_occurred' logger='my_awesome_project.my_awesome_module' request_id='3a8f801c-072b-4805-8f38-e1337f363ed4' user_id=1 ip='0.0.0.0' bar='Buz'

Then you can search with commands like:

$ cat logs/flat_line.log | grep request_id='3a8f801c-072b-4805-8f38-e1337f363ed4'

With django-structlog and json

>>> import structlog
>>> logger = structlog.get_logger(__name__)
>>> logger.info("an_error_occurred", bar="Buz")

{"request_id": "3a8f801c-072b-4805-8f38-e1337f363ed4", "user_id": 1, "ip": "0.0.0.0", "event": "an_error_occurred", "timestamp": "2019-04-13T19:39:31.089925Z", "logger": "my_awesome_project.my_awesome_module", "level": "info", "bar": "Buz"}

Then you can search with commands like:

$ cat logs/json.log | jq '.[] | select(.request_id="3a8f801c-072b-4805-8f38-e1337f363ed4")' -s

Getting Started

These steps will show how to integrate the middleware to your awesome application.

Installation

Install the library

pip install django-structlog

Add middleware

MIDDLEWARE = [
    # ...
    'django_structlog.middlewares.RequestMiddleware',
]

Add appropriate structlog configuration to your settings.py

import structlog

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "json_formatter": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.processors.JSONRenderer(),
        },
        "plain_console": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.dev.ConsoleRenderer(),
        },
        "key_value": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.processors.KeyValueRenderer(key_order=['timestamp', 'level', 'event', 'logger']),
        },
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "formatter": "plain_console",
        },
        "json_file": {
            "class": "logging.handlers.WatchedFileHandler",
            "filename": "logs/json.log",
            "formatter": "json_formatter",
        },
        "flat_line_file": {
            "class": "logging.handlers.WatchedFileHandler",
            "filename": "logs/flat_line.log",
            "formatter": "key_value",
        },
    },
    "loggers": {
        "django_structlog": {
            "handlers": ["console", "flat_line_file", "json_file"],
            "level": "INFO",
        },
        # Make sure to replace the following logger's name for yours
        "django_structlog_demo_project": {
            "handlers": ["console", "flat_line_file", "json_file"],
            "level": "INFO",
        },
    }
}

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,
        structlog.stdlib.filter_by_level,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.processors.UnicodeDecoder(),
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    logger_factory=structlog.stdlib.LoggerFactory(),
    cache_logger_on_first_use=True,
)

Start logging with structlog instead of logging.

import structlog
logger = structlog.get_logger(__name__)

Extending Request Log Metadata

By default only a request_id and the user_id are bound from the request but pertinent log metadata may vary from a project to another.

If you need to add more metadata from the request you can implement a convenient signal receiver to bind them. You can also override existing bound metadata the same way.

from django.dispatch import receiver

from django_structlog.signals import bind_extra_request_metadata
import structlog


@receiver(bind_extra_request_metadata)
def bind_user_email(request, logger, **kwargs):
    structlog.contextvars.bind_contextvars(user_email=getattr(request.user, 'email', ''))

Standard Loggers

It is also possible to log using standard python logger.

In your formatters, add the foreign_pre_chain section, and then add structlog.contextvars.merge_contextvars:

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "json_formatter": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.processors.JSONRenderer(),
            # Add this section:
            "foreign_pre_chain": [
                structlog.contextvars.merge_contextvars, # <---- add this
                # customize the rest as you need
                structlog.processors.TimeStamper(fmt="iso"),
                structlog.stdlib.add_logger_name,
                structlog.stdlib.add_log_level,
                structlog.stdlib.PositionalArgumentsFormatter(),
            ],
        },
    },
    ...
 }

Example outputs

Flat lines file (`logs/flat_lines.log`)

timestamp='2019-04-13T19:39:29.321453Z' level='info' event='request_started' logger='django_structlog.middlewares.request' request_id='c53dff1d-3fc5-4257-a78a-9a567c937561' user_id=1 ip='0.0.0.0' request=GET / user_agent='Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.86 Safari/537.36'
timestamp='2019-04-13T19:39:29.345207Z' level='info' event='request_finished' logger='django_structlog.middlewares.request' request_id='c53dff1d-3fc5-4257-a78a-9a567c937561' user_id=1 ip='0.0.0.0' code=200
timestamp='2019-04-13T19:39:31.086155Z' level='info' event='request_started' logger='django_structlog.middlewares.request' request_id='3a8f801c-072b-4805-8f38-e1337f363ed4' user_id=1 ip='0.0.0.0' request=POST /success_task user_agent='Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.86 Safari/537.36'
timestamp='2019-04-13T19:39:31.089925Z' level='info' event='Enqueuing successful task' logger='django_structlog_demo_project.home.views' request_id='3a8f801c-072b-4805-8f38-e1337f363ed4' user_id=1 ip='0.0.0.0'
timestamp='2019-04-13T19:39:31.147590Z' level='info' event='task_enqueued' logger='django_structlog.middlewares.celery' request_id='3a8f801c-072b-4805-8f38-e1337f363ed4' user_id=1 ip='0.0.0.0' child_task_id='6b11fd80-3cdf-4de5-acc2-3fd4633aa654'
timestamp='2019-04-13T19:39:31.153081Z' level='info' event='This is a successful task' logger='django_structlog_demo_project.taskapp.celery' task_id='6b11fd80-3cdf-4de5-acc2-3fd4633aa654' request_id='3a8f801c-072b-4805-8f38-e1337f363ed4' user_id=1 ip='0.0.0.0'
timestamp='2019-04-13T19:39:31.160043Z' level='info' event='request_finished' logger='django_structlog.middlewares.request' request_id='3a8f801c-072b-4805-8f38-e1337f363ed4' user_id=1 ip='0.0.0.0' code=201
timestamp='2019-04-13T19:39:31.162372Z' level='info' event='task_succeed' logger='django_structlog.middlewares.celery' task_id='6b11fd80-3cdf-4de5-acc2-3fd4633aa654' request_id='3a8f801c-072b-4805-8f38-e1337f363ed4' user_id=1 ip='0.0.0.0' result='None'

Json file (`logs/json.log`)

{"request_id": "c53dff1d-3fc5-4257-a78a-9a567c937561", "user_id": 1, "ip": "0.0.0.0", "request": "GET /", "user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.86 Safari/537.36", "event": "request_started", "timestamp": "2019-04-13T19:39:29.321453Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "c53dff1d-3fc5-4257-a78a-9a567c937561", "user_id": 1, "ip": "0.0.0.0", "code": 200, "event": "request_finished", "timestamp": "2019-04-13T19:39:29.345207Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "3a8f801c-072b-4805-8f38-e1337f363ed4", "user_id": 1, "ip": "0.0.0.0", "request": "POST /success_task", "user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.86 Safari/537.36", "event": "request_started", "timestamp": "2019-04-13T19:39:31.086155Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "3a8f801c-072b-4805-8f38-e1337f363ed4", "user_id": 1, "ip": "0.0.0.0", "event": "Enqueuing successful task", "timestamp": "2019-04-13T19:39:31.089925Z", "logger": "django_structlog_demo_project.home.views", "level": "info"}
{"request_id": "3a8f801c-072b-4805-8f38-e1337f363ed4", "user_id": 1, "ip": "0.0.0.0", "child_task_id": "6b11fd80-3cdf-4de5-acc2-3fd4633aa654", "event": "task_enqueued", "timestamp": "2019-04-13T19:39:31.147590Z", "logger": "django_structlog.middlewares.celery", "level": "info"}
{"task_id": "6b11fd80-3cdf-4de5-acc2-3fd4633aa654", "request_id": "3a8f801c-072b-4805-8f38-e1337f363ed4", "user_id": 1, "ip": "0.0.0.0", "event": "This is a successful task", "timestamp": "2019-04-13T19:39:31.153081Z", "logger": "django_structlog_demo_project.taskapp.celery", "level": "info"}
{"request_id": "3a8f801c-072b-4805-8f38-e1337f363ed4", "user_id": 1, "ip": "0.0.0.0", "code": 201, "event": "request_finished", "timestamp": "2019-04-13T19:39:31.160043Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"task_id": "6b11fd80-3cdf-4de5-acc2-3fd4633aa654", "request_id": "3a8f801c-072b-4805-8f38-e1337f363ed4", "user_id": 1, "ip": "0.0.0.0", "result": "None", "event": "task_succeed", "timestamp": "2019-04-13T19:39:31.162372Z", "logger": "django_structlog.middlewares.celery", "level": "info"}

Upgrade Guide

Upgrading to 3.0+

django-structlog now use structlog.contextvars.bind_contextvars instead of threadlocal.

Minimum requirements

requires python 3.7+
requires structlog 21.4.0+

Changes you need to do

1. Update structlog settings

add structlog.contextvars.merge_contextvars as first processors
remove context_class=structlog.threadlocal.wrap_dict(dict),
(if you use standard loggers) add structlog.contextvars.merge_contextvars in foreign_pre_chain
(if you use standard loggers) remove django_structlog.processors.inject_context_dict,

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars, # <---- add this
        structlog.stdlib.filter_by_level,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.processors.UnicodeDecoder(),
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    # context_class=structlog.threadlocal.wrap_dict(dict), # <---- remove this
    logger_factory=structlog.stdlib.LoggerFactory(),
    cache_logger_on_first_use=True,
)

# If you use standard logging
LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "json_formatter": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.processors.JSONRenderer(),
            "foreign_pre_chain": [
                structlog.contextvars.merge_contextvars, # <---- add this
                # django_structlog.processors.inject_context_dict, # <---- remove this
                structlog.processors.TimeStamper(fmt="iso"),
                structlog.stdlib.add_logger_name,
                structlog.stdlib.add_log_level,
                structlog.stdlib.PositionalArgumentsFormatter(),
            ],
        },
    },
    ...
 }

2. Replace all `logger.bind` with `structlog.contextvars.bind_contextvars`

@receiver(bind_extra_request_metadata)
def bind_user_email(request, logger, **kwargs):
   # logger.bind(user_email=getattr(request.user, 'email', ''))
   structlog.contextvars.bind_contextvars(user_email=getattr(request.user, 'email', ''))

Upgrading to 2.0+

django-structlog was originally developed using the debug configuration ExceptionPrettyPrinter which led to incorrect handling of exception.

remove structlog.processors.ExceptionPrettyPrinter(), of your processors.
make sure you have structlog.processors.format_exc_info, in your processors if you want appropriate exception logging.

Running the tests

Note: For the moment redis is needed to run the tests. The easiest way start docker's demo.

docker-compose up --build

In another shell

pip install -r requirements.txt
env CELERY_BROKER_URL=redis://0.0.0.0:6379 pytest test_app
env CELERY_BROKER_URL=redis://0.0.0.0:6379 DJANGO_SETTINGS_MODULE=config.settings.test_demo_app pytest django_structlog_demo_project

Demo app

docker-compose up --build

Open http://0.0.0.0:8000/ in your browser.

Navigate while looking into the log files and shell's output.

Authors

Jules Robichaud-Gagnon - Initial work - jrobichaud

See also the list of contributors who participated in this project.

Acknowledgments

Big thanks to @ferd for his bad opinions that inspired the author enough to spend time on this library.
This issue helped the author to figure out how to integrate structlog in Django.
This stack overflow question was also helpful.

License

This project is licensed under the MIT License - see the LICENSE file for details