Django Structlog is not printing or writing log message to console or file

Question

I have installed django-structlog 1.4.1 for my Django project. I have followed all the steps which has been described in that link.

In my settings.py file:

import structlog


MIDDLEWARE = [
    'django.middleware.security.SecurityMiddleware',
    'django.contrib.sessions.middleware.SessionMiddleware',
    'django.middleware.common.CommonMiddleware',
    'django.middleware.csrf.CsrfViewMiddleware',
    'django.contrib.auth.middleware.AuthenticationMiddleware',
    'django.contrib.messages.middleware.MessageMiddleware',
    'django.middleware.clickjacking.XFrameOptionsMiddleware',
    'django_structlog.middlewares.RequestMiddleware',
]

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": "log/json.log",
            "formatter": "json_formatter",
        },
        "flat_line_file": {
            "class": "logging.handlers.WatchedFileHandler",
            "filename": "log/flat_line.log",
            "formatter": "key_value",
        },
    },
    "loggers": {
        "django_structlog": {
            "handlers": ["console", "flat_line_file", "json_file"],
            "level": "DEBUG",
        },
        "django_structlog_demo_project": {
            "handlers": ["console", "flat_line_file", "json_file"],
            "level": "DEBUG",
        },
    }
}

structlog.configure(
    processors=[
        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.processors.ExceptionPrettyPrinter(),
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    context_class=structlog.threadlocal.wrap_dict(dict),
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)

In my views.py:

from django.http.response import HttpResponse
import structlog
logger = structlog.get_logger(__name__)

def func(request):
    logger.debug("debug message", bar="Buz")
    logger.info("info message", bar="Buz")
    logger.warning("warning message", bar="Buz")
    logger.error("error message", bar="Buz")
    logger.critical("critical message", bar="Buz")

    return HttpResponse('success')

Output in json.log:

{"request_id": "7903fdfb-e99a-4360-a8f0-769696520cc9", "user_id": null, "ip": "127.0.0.1", "request": "<WSGIRequest: GET '/test'>", "user_agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.88 Safari/537.36", "event": "request_started", "timestamp": "2020-02-12T05:11:23.877111Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "7903fdfb-e99a-4360-a8f0-769696520cc9", "user_id": null, "ip": "127.0.0.1", "code": 200, "request": "<WSGIRequest: GET '/test'>", "event": "request_finished", "timestamp": "2020-02-12T05:11:23.879736Z", "logger": "django_structlog.middlewares.request", "level": "info"}

Output in flat_line.log:

timestamp='2020-02-12T05:11:23.877111Z' level='info' event='request_started' logger='django_structlog.middlewares.request' request_id='7903fdfb-e99a-4360-a8f0-769696520cc9' user_id=None ip='127.0.0.1' request=<WSGIRequest: GET '/test'> user_agent='Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.88 Safari/537.36'
timestamp='2020-02-12T05:11:23.879736Z' level='info' event='request_finished' logger='django_structlog.middlewares.request' request_id='7903fdfb-e99a-4360-a8f0-769696520cc9' user_id=None ip='127.0.0.1' code=200 request=<WSGIRequest: GET '/test'>

Output in console:

2020-02-12T05:11:23.877111Z [info     ] request_started                [django_structlog.middlewares.request] ip=127.0.0.1 request=<WSGIRequest: GET '/test'> request_id=7903fdfb-e99a-4360-a8f0-769696520cc9 user_agent=Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.88 Safari/537.36 user_id=None
{'request_id': '7903fdfb-e99a-4360-a8f0-769696520cc9', 'user_id': None, 'ip': '127.0.0.1', 'bar': 'Buz', 'event': 'warning message', 'timestamp': '2020-02-12T05:11:23.879035Z', 'logger': 'operational.views.core_view', 'level': 'warning'}
{'request_id': '7903fdfb-e99a-4360-a8f0-769696520cc9', 'user_id': None, 'ip': '127.0.0.1', 'bar': 'Buz', 'event': 'error message', 'timestamp': '2020-02-12T05:11:23.879292Z', 'logger': 'operational.views.core_view', 'level': 'error'}
{'request_id': '7903fdfb-e99a-4360-a8f0-769696520cc9', 'user_id': None, 'ip': '127.0.0.1', 'bar': 'Buz', 'event': 'critical message', 'timestamp': '2020-02-12T05:11:23.879468Z', 'logger': 'operational.views.core_view', 'level': 'critical'}
2020-02-12T05:11:23.879736Z [info     ] request_finished               [django_structlog.middlewares.request] code=200 ip=127.0.0.1 request=<WSGIRequest: GET '/test'> request_id=7903fdfb-e99a-4360-a8f0-769696520cc9 user_id=None
[12/Feb/2020 05:11:23] "GET /test HTTP/1.1" 200 7

My issues are:

• 'info' and 'debug' level log message is not showing at the console.
• Any type of log message is not writing at the log files except "event='request_started'" and "event='request_finished'"

I want same message in all of my log files and console. How can i achieve this?

Answer 1

I haven't used django-structlog (but written structlog 🤓) and this looks like django_structlog_demo_project is not the name of the logger of your application and hence the settings don't apply (default log level is INFO).

You can either fix the name or since your configurations are identical, I would suggest to delete the example logger and rename the first one to root which should have a global effect.

This is sadly a very common gotcha with standard library's logging.