beginnerintermediateadvanced

Django · Section 78

Structured Logging

Level: intermediate
Read: 32 min
Concepts: 3

Django's `LOGGING` has four kinds of moving part, and most confusion disappears once you can name which one you need. A logger is the named bucket you write to, a handler decides where a record goes, a formatter renders it, and a filter decides whether it continues — and can also add fields to it, which is the trick that gets a request id onto records emitted by Django itself. Reading the pipeline in order also explains the two classic bugs. A record is filtered at four separate points — the logger's level, the logger's filters, each handler's level, each handler's filters — so "my line does not appear" is usually one of those gates rather than a broken configuration. And records climb the dotted name hierarchy by default, so attaching a handler to a child logger while root also has one emits every line twice; `propagate: False` on the loggers you configure is the fix. Keep `disable_existing_loggers: False` as well, or you quietly lose `django.request`, the logger that already reports every 5XX at ERROR and every 4XX at WARNING. The second shift is from sentences to records. A structured line is a JSON object with a short, *stable* message and typed fields, because stability is what makes the message a grouping key you can count, compare across deploys and alert on — interpolate an order id into the text and you lose all of it, exactly as interpolation breaks error grouping. Carry the fields that join a record to something else: the request id, a trace id, a tenant id, and a user id where it is appropriate to store one. The third part is not a style question. The roadmap lists what must never be logged — passwords, access tokens, refresh tokens, API secrets, payment credentials, unnecessary personal information — and logs are the least protected copy of your data, shipped to third parties and kept for months. So make the defence structural rather than a habit: an allow-list in the formatter, since a block-list fails open on every field name nobody thought of; a redacting filter for secrets embedded in otherwise-fine text; and `sensitive_variables` / `sensitive_post_parameters` to close the traceback path, where the password your log calls carefully avoided otherwise arrives in full.

Django overview

Python Django Full Course for Beginners | Complete All-in-One Tutorial | 3 HoursDave Gray

What is true here

Four components, and four gates a record must pass before it is emitted.
Records propagate up the name hierarchy — propagate: False is what stops duplicate lines.
A stable message plus fields in extra; interpolation destroys grouping.
Allow-list what a formatter emits, because a block-list fails open.
Tracebacks carry locals and POST data — mark them sensitive or the secret leaks there.

What you will be able to do

Explain why a log line does not appear, or appears twice, without guessing
Get a request id onto every record without touching call sites
Write logs that answer questions six weeks later
Build redaction that survives the field somebody adds next year

One log call, four gates, and the three places a secret can escape

log.warning("payment declined", extra={…})

Gate 1 — the logger's level

below it, the record ends here and no handler can recover it

Gate 2 — the logger's filters

also where enrichment happens: request_id is added here

Climb to the parent logger?

orders.services → orders → root, unless propagate is False

Emitted twice

a handler on the child AND on root

Gate 3 + 4 — each handler's level and filters

a handler at ERROR ignores the WARNING the logger passed

Redacting filter

tokens inside URLs and messages

Formatter — allow-list

only named fields are emitted; a new field is invisible by default

JSON on stdout

shipped, indexed, retained for months

An unhandled exception

a different path entirely

Traceback with locals + POST

@sensitive_variables / @sensitive_post_parameters

The four parts, and the four gates

Loggers, handlers, formatters and filters — plus propagation, which explains the duplicate-line bug.

Loggers, handlers, formatters, filters — and levels

coreintermediate

Django's `LOGGING` setting has four kinds of moving part, and knowing which one to reach for removes most of the confusion. A **logger** is the named bucket you write to — `logging.getLogger(__name__)`. A **handler** decides where a record goes: the console, a file, an email. A **formatter** turns the record into text. A **filter** decides whether a record continues, and can also add fields to it. Records travel up the name hierarchy, so `orders.services` also reaches `orders` and the root — which is why one misplaced handler can double every line you emit.

Think of it as

Read the pipeline in order and most surprises explain themselves. You log to a logger; the logger's own level filters first; then filters attached to the logger run; then the record is passed to each of that logger's handlers, which apply their *own* level and their own filters; and finally a formatter renders it. Two levels and two filter stages mean a record can be dropped in four different places, and "my log line does not appear" is almost always one of them rather than a broken configuration. Then there is propagation. Logger names are dotted paths and records travel upward by default, so a record from `orders.services` is also offered to `orders` and to the root logger. That is a good default — it lets you configure handlers once at the root — and it is exactly what produces duplicate lines when someone attaches a handler to a child logger as well. `propagate: False` stops the climb, and it belongs on the specific loggers you have deliberately configured. The last piece is that Django merges your `LOGGING` with its own defaults rather than replacing them, and `disable_existing_loggers` controls whether the loggers already created keep working. Turning it on is a common way to silently lose `django.request` — the logger that reports every 5XX — which is usually the last thing you want gone from production.

python

log = logging.getLogger(__name__)      # "orders.services" — reaches "orders" and root
log.warning("stock low", extra={"sku": sku, "remaining": remaining})

What we're doing: A production `LOGGING` block that keeps Django's own loggers, adds context, and emits no duplicates.

shop/settings/production.pypython

LOGGING = {
    "version": 1,
    # Keep Django's own loggers alive. True here silently removes django.request.
    "disable_existing_loggers": False,

    "formatters": {
        "json": {"()": "observability.formatters.JSONFormatter"},
        "console": {"format": "%(levelname)s %(name)s %(request_id)s %(message)s"},
    },

    "filters": {
        # Enrichment, not rejection: adds request_id to EVERY record.
        "request_id": {"()": "observability.request_id.RequestIDFilter"},
        "require_debug_false": {"()": "django.utils.log.RequireDebugFalse"},
    },

    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "formatter": "json",
            "filters": ["request_id"],
        },
        "mail_admins": {
            "class": "django.utils.log.AdminEmailHandler",
            "level": "ERROR",
            "filters": ["require_debug_false"],      # never email from a dev machine
        },
    },

    "loggers": {
        "django.request": {
            "handlers": ["console", "mail_admins"],
            "level": "WARNING",
            "propagate": False,                      # or root logs it a second time
        },
        "django.security": {
            "handlers": ["console"],
            "level": "WARNING",
            "propagate": False,
        },
        "orders": {"handlers": ["console"], "level": "INFO", "propagate": False},
    },

    "root": {"handlers": ["console"], "level": "INFO"},
}

4: The one-word setting that costs people their 5XX logging. Django merges this configuration with its defaults; disabling existing loggers throws away the ones it already created.
12–13: A filter used for enrichment. It returns `True` for every record but sets an attribute first, which is how `request_id` reaches lines emitted by Django and by third-party libraries.
26: `RequireDebugFalse` passes records "only when `settings.DEBUG` is `False`", which is what stops a developer's local error from emailing the admins.
30–34: Two handlers for one logger — console for everything at WARNING and above, email for ERROR and above, since the handler applies its own level on top of the logger's.
39: One entry for your own top-level package. Child loggers such as `orders.services` inherit it, so per-module configuration is rarely needed.
33–42: `propagate: False` on each configured logger. Without it every record is also handled by root, and every line appears twice — the most common Django logging bug.

Why this works: Django's existing loggers keep working, one filter enriches everything without touching call sites, handler levels do the fine-grained selection, and propagation is stopped exactly where handlers were attached.

Adding a handler to a child logger and getting every line twice

Wrong

python

"loggers": {
    "orders": {"handlers": ["console"], "level": "INFO"},    # no propagate key
},
"root": {"handlers": ["console"], "level": "INFO"},
# every record from orders.* is emitted by BOTH handlers

Better

python

"loggers": {
    "orders": {"handlers": ["console"], "level": "INFO", "propagate": False},
},
"root": {"handlers": ["console"], "level": "INFO"},

What you see: Every log line appears twice, log volume and bill double, and searches return two copies of each result — which also makes count-based alerts read exactly twice as high as reality.

Why: Records climb the dotted name hierarchy by default: a record on `orders.services` is offered to `orders` and then to the root logger, and every handler along that path emits it. Attaching a handler to `orders` while root also has one therefore delivers the record twice. `propagate: False` stops the climb at the logger you configured. The rule that avoids the problem entirely is to attach handlers in one place — usually root — and use child loggers only to set levels.

One logger entry, and what each key decides

"django.request": {"handlers": ["console", "errors"], "level": "WARNING", "propagate": False}

"django.request"

the bucket, by dotted name — Django writes here already: 5XX responses at ERROR and 4XX at WARNING, with `status_code` and the `request` attached to the record. You are configuring an existing logger, not creating one.

"handlers"

where records go from here — A list, because one record can go to several destinations. Each handler then applies its own level and its own filters, independently of the ones below.

["console", "errors"]

the destinations by name — These must exist in the `handlers` dict. A typo here is silent — the record is simply never delivered anywhere.

"level": "WARNING"

the first of two gates — Records below this never leave the logger. A handler set to DEBUG cannot recover them, which is why "I set the handler to DEBUG and see nothing" is so common.

"propagate": False

stop climbing the hierarchy — Without this the record is also offered to the root logger, so a root handler emits it a second time. This single key is the usual cause of every line appearing twice.

Django's own loggers, and what each gives you free

Django's own loggers, and what each gives you free
Logger	Emits	At
`django.request`	5XX responses	ERROR (4XX at WARNING), with `status_code` and `request`
`django.server`	runserver request handling	ERROR for 5XX, WARNING for 4XX, INFO otherwise
`django.db.backends`	every application SQL statement	DEBUG, with `duration`, `sql`, `params`, `alias`
`django.security.*`	`SuspiciousOperation` and security errors	WARNING, or ERROR if it reaches the WSGI handler

Together

python

# django.db.backends: "SQL logging is only enabled when settings.DEBUG is set
# to True, regardless of the logging level or handlers that are installed."

Remember: Four parts and four gates: a record passes the logger's level, the logger's filters, each handler's level, and each handler's filters — so a missing line is usually one of those, not a broken config. Records climb the dotted hierarchy, so attach handlers in one place (root) and set `propagate: False` on any logger you do give handlers to, or every line appears twice. Keep `disable_existing_loggers: False` so Django's own `django.request` survives, use filters to *add* fields rather than only to reject, and remember `django.db.backends` logs SQL only when `DEBUG` is `True`.

Records, not sentences

JSON output, a stable message, and the context fields that make a log searchable six weeks later.

JSON logs, and the context fields worth carrying

coreintermediate

A structured log line is a JSON object rather than a sentence, so every value is a field you can search, filter and aggregate on. `log.info("order settled", extra={"order_id": 8412, "amount": "49.00"})` produces a record whose fields a log system can index — instead of a string somebody has to write a regular expression against later. Three fields are worth carrying on nearly everything: the `request_id` that ties the record to the rest of the request, a trace id if you emit traces, and a user id where it is appropriate to store one.

Think of it as

The shift is from writing sentences for a person to emitting records for a query. A human-readable line is optimised for the moment you are watching a console; a structured record is optimised for the moment six weeks later when you need every failed settlement over £100 for one customer. Only the second case is where log data earns its cost, so the message should be a short stable label and everything variable should be a field. Stability matters more than it looks: once the message is a constant, it becomes a groupable key — you can count occurrences, alert on a rate, and compare across deploys — whereas interpolating values into the text produces a unique string per event and destroys all of that. That is the same reasoning that keeps error grouping working. The second half is deciding what context to attach. Anything you would want to filter by belongs there, and the fields that pay for themselves are the ones that join a record to something else: the request id joins it to the rest of the request and to the trace, a tenant or organisation id joins it to a customer, an object id joins it to a row you can go and read. A user id is worth having and is also the field that most often turns a log into personal data, so prefer the surrogate key over an email address, and be sure the retention on your log store is something you are willing to defend. Field names should be consistent across the codebase — `order_id` everywhere, never `orderId` in one place and `order` in another — because a query that has to know three spellings is a query nobody writes.

python

log.info("order settled", extra={"order_id": order.id, "amount": str(order.total)})

What we're doing: A JSON formatter that renders the standard fields plus whatever `extra` was passed, without letting anything unexpected through.

observability/formatters.pypython

import json, logging

# Everything logging puts on a record itself. Anything NOT in here came from
# extra={...}, which is exactly what we want to emit.
RESERVED = set(logging.LogRecord("", 0, "", 0, "", (), None).__dict__) | {
    "message", "asctime", "taskName",
}
ALLOWED_EXTRA = {
    "request_id", "trace_id", "user_id", "tenant_id", "route",
    "order_id", "sku", "amount", "duration_ms", "db_ms", "db_queries",
}


class JSONFormatter(logging.Formatter):
    def format(self, record):
        payload = {
            "ts": self.formatTime(record, "%Y-%m-%dT%H:%M:%S%z"),
            "level": record.levelname,
            "logger": record.name,
            "msg": record.getMessage(),
            "request_id": getattr(record, "request_id", "-"),
        }

        for key, value in record.__dict__.items():
            if key in RESERVED or key not in ALLOWED_EXTRA:
                continue                        # an allow-list, not a block-list
            payload[key] = value

        if record.exc_info:
            payload["exc"] = self.formatException(record.exc_info)

        return json.dumps(payload, default=str)


# Django's own records come through here too, and bring their own context:
#   django.request      -> status_code
#   django.db.backends  -> duration, sql, params, alias   (DEBUG only)

5–7: Building the reserved set from a real `LogRecord` rather than hard-coding a list means it stays correct across Python versions instead of drifting.
8–11: The allow-list is the important design choice, and the next concept explains why: a block-list only excludes the field names somebody thought of.
21: `request_id` is read from the record rather than passed at the call site, because the filter from §77 has already put it there — including on Django's own records.
24–27: The loop emits `extra` keys and nothing else. A field that is not on the list is dropped silently, which is the safe direction to fail.
33: `default=str` keeps a `Decimal`, a `UUID` or a `datetime` from raising during serialisation. A formatter that can raise turns a logging call into an application error.

Why this works: Every record leaves as one JSON object with a stable set of keys, the request id arrives automatically, and only fields that were deliberately named can appear.

Interpolating values into the message

Wrong

python

log.warning(f"payment declined for order {order.id}, amount {order.total}")
# one distinct message per order: not groupable, not countable, not alertable

Better

python

log.warning("payment declined", extra={"order_id": order.id, "amount": str(order.total)})
# one message, two fields: group by message, filter by field

What you see: Log searches return everything or nothing depending on the regular expression, and "how many declines were there this hour" cannot be answered without parsing free text.

Why: A message with values interpolated into it is a unique string per event, so it cannot be used as a grouping key — you lose counts, rates, comparisons across deploys and any alert built on the message. Keeping the message constant and moving the variables into fields preserves both halves: the message groups, the fields filter. It is the same rule that keeps error tracking useful, and it applies for the same reason.

The same event, written two ways — and the questions each one can answer

A sentence

+Readable in a console, and nowhere else
+Every value is embedded in the text
+Searching means regular expressions over prose
+Reword the message and every saved search breaks
+"All declines over £100 for tenant 42, last week" is impractical

A record

−A stable message plus typed fields
−Every value is indexed and filterable
−Searching is a field query
−The message is a groupable key you can count and alert on
−That question is one filter expression

The fields worth carrying, and what each one joins to

The fields worth carrying, and what each one joins to
Field	Joins the record to	Notes
`request_id`	every other record from the same request, and the trace	injected by a filter, never passed by hand
`trace_id` / `span_id`	the trace in your tracing backend	only if you emit traces
`user_id`	a person	surrogate key, not an email — this is personal data
`tenant_id`	a customer	the field that makes "is it only them?" answerable in one query
`route`	the endpoint	the URL pattern, not the path
domain ids (`order_id`, `sku`)	a row you can go and read	consistent names across the whole codebase

Together

python

log.warning("payment declined",
            extra={"order_id": order.id, "tenant_id": order.tenant_id, "amount": str(order.total)})

Remember: Write records, not sentences: a short stable message plus typed fields in `extra`. Stability is what makes the message a groupable key — interpolate a value into it and you lose counts, rates and alerts, exactly as with error grouping. Carry the joining fields on everything (`request_id`, a trace id, `tenant_id`, and a `user_id` where appropriate), keep one spelling per concept across the codebase, and let an allow-list decide what a formatter emits. Never log a whole model or request: name the fields, or the line's contents become a function of the entire codebase.

What must never get in

The roadmap's "do not log" list, made structural — and the traceback path that bypasses all of it.

Keeping secrets out of logs

coreintermediate

The roadmap lists what must never reach a log: passwords, access tokens, refresh tokens, API secrets, payment credentials, and unnecessary personal information. Logs are the least protected copy of your data — they are shipped to third parties, kept for months, and readable by everyone on the team — so a secret in a log is a secret that has leaked. Build the defence into the pipeline rather than into people's memory: an allow-list in the formatter, a redacting filter for what does get through, and Django's `sensitive_variables` / `sensitive_post_parameters` so tracebacks do not carry the values instead.

Think of it as

Treat the log store as an untrusted, widely-readable, long-lived copy of whatever you send it, because in practice that is what it is. It is usually a third-party service, its access controls are usually much looser than the database's, and retention is measured in months — so the standard for what may go in is closer to "would I paste this into a shared document" than to "is this in our database anyway". Once framed that way, the design follows: redaction cannot be a habit, because habits are per call site and the leak is always the call site nobody thought about. It has to be structural, and there are three layers. First, an allow-list in the formatter, so a field can only appear if someone named it — a block-list only excludes the names you thought of, and `card_number` gets caught while `cardNumber`, `pan` and `payment_details` do not. Second, a redacting filter for values that pass through legitimately-named fields, since a token can arrive inside a URL or an error message. Third, Django's error reporting, which is the path people forget: an unhandled exception produces a traceback with every local variable and every POST parameter, so the password your log lines carefully avoid is present in the crash report unless you mark it. And when something does leak, treat it as a leak — rotate the credential, because you cannot know who read the log, and deleting the line does not undo the copies already shipped downstream.

python

@sensitive_variables("password", "token")          # keep locals out of tracebacks
@sensitive_post_parameters("password", "card_number")

What we're doing: Put the defence in the pipeline, and close the traceback path the pipeline cannot see.

observability/redaction.py + accounts/views.pypython

import logging, re

TOKEN_PATTERNS = [
    (re.compile(r"(Bearer\s+)[A-Za-z0-9._-]+"), r"\1[REDACTED]"),
    (re.compile(r"([?&](?:token|api_key|signature)=)[^&\s]+"), r"\1[REDACTED]"),
    (re.compile(r"\b\d{13,19}\b"), "[REDACTED-PAN]"),
]


class RedactingFilter(logging.Filter):
    """Second layer: catches secrets inside otherwise-allowed text."""

    def filter(self, record):
        message = record.getMessage()
        for pattern, replacement in TOKEN_PATTERNS:
            message = pattern.sub(replacement, message)
        record.msg, record.args = message, ()
        return True                       # a filter that redacts, not one that rejects


# The first layer lives in the formatter from the previous concept:
# only keys in ALLOWED_EXTRA are ever emitted, so a new "password" field
# added by someone in a hurry cannot reach the log at all.


# ---- accounts/views.py: the path neither layer can see -----------------
from django.views.decorators.debug import sensitive_post_parameters, sensitive_variables


@sensitive_post_parameters("password", "password_confirm", "card_number")
@sensitive_variables("password", "token", "raw_card")
def register(request):
    password = request.POST["password"]
    token = issue_token(password)
    raise RuntimeError("boom")      # traceback shows password = ********, not the value


def update_profile(request, user):
    log.info("profile updated", extra={
        "user_id": user.id,
        "changed_fields": sorted(form.changed_data),    # names, never values
    })

3–7: Patterns for the shapes that slip through legitimately-named fields: an `Authorization` header echoed into a message, a token in a query string, a long digit run that looks like a card number.
18: Returning `True` after rewriting is the filter-as-transformer pattern. The record continues; only its text has changed.
21–23: The allow-list is the primary defence and this is the backstop. Two layers, because the first cannot see inside a value and the second cannot know which fields are safe.
30–34: The decorators cover the crash path. Without them the traceback in your error tracker carries the password as a local variable and in the POST data — the exact value every log call was careful to avoid.
38–41: Field *names* rather than values: the audit question is almost always "what changed", and answering it with names carries none of the data.

Why this works: The allow-list makes an unnamed field impossible to emit, the redacting filter catches secrets embedded in text that is otherwise fine, and the decorators close the traceback path that neither of them can reach.

Using a block-list of sensitive field names

Wrong

python

SENSITIVE = {"password", "token", "secret"}

for key, value in record.__dict__.items():
    payload[key] = "[REDACTED]" if key in SENSITIVE else value
# passes: card_number, cardNumber, pan, cvv, ssn, refresh_token, api_key,
#         authorization, session_key, otp, and everything added next year

Better

python

ALLOWED_EXTRA = {"request_id", "user_id", "tenant_id", "order_id", "route", "duration_ms"}

for key, value in record.__dict__.items():
    if key in ALLOWED_EXTRA:
        payload[key] = value
# a new field is invisible until someone deliberately adds it here

What you see: The redaction looks thorough in review and a field named `pan`, `otp` or `cardNumber` sails straight through — usually added months later by someone who never saw the block-list.

Why: A block-list has to enumerate every dangerous name, including ones nobody has invented yet, and it fails open: an unlisted field is emitted. An allow-list fails closed, so the worst outcome of forgetting is a missing field in a dashboard rather than a credential in a log store. The asymmetry is what matters — one failure mode is an inconvenience you notice immediately, and the other is a leak you may never notice. It also makes the policy reviewable, because the complete set of things that can be logged is one readable constant.

Three layers, because one is always bypassed

At the call site

Name fields, never dump objects

extra={"user_id": u.id}, not u.__dict__

Log which fields changed

the names carry the audit value, the values carry the risk

Depends on memory

so it fails exactly where nobody was thinking

In the pipeline

Allow-list in the formatter

a field appears only if someone named it

Redacting filter over the text

catches tokens embedded in URLs and messages

One place to review

the whole policy is two objects, not every call site

In error reporting

@sensitive_variables()

locals are hidden from the traceback

@sensitive_post_parameters()

POST values are hidden from the report

Crashes carry everything

the password your logs avoided is in the traceback

Where each leak comes from, and what stops it

Where each leak comes from, and what stops it
Path	Example	Defence
a deliberate log call	`log.info("login", extra={"password": pw})`	allow-list in the formatter
a whole object	`extra={"request": request.POST}`	allow-list, plus never logging containers
a value inside an allowed field	a token in a URL in `message`	a redacting filter over the rendered text
an unhandled exception	locals and POST in the traceback	`sensitive_variables` / `sensitive_post_parameters`
a third-party library	a client logging its own request headers	set that logger's level, or filter it
SQL logging	query `params` containing personal data	`django.db.backends` is DEBUG-only — keep `DEBUG` off

Together

python

@sensitive_variables("password", "token")
@sensitive_post_parameters("password", "card_number")
def login(request): ...

Remember: Logs are the least protected, longest-lived copy of your data, so a logged secret is a leaked secret — rotate it rather than deleting the line, because you cannot know who read it or where it was forwarded. Make redaction structural: an allow-list in the formatter so a field appears only if someone named it (a block-list fails open on every name nobody thought of), plus a redacting filter for tokens embedded in otherwise-fine text. And close the path neither layer sees with `@sensitive_variables()` and `@sensitive_post_parameters()`, or the password your log calls avoided arrives in the traceback instead.