Structured JSON Records · Python — interview questions

What does logging's extra= dict add to a LogRecord, and when does it raise KeyError?

middlemust knowfreq 55%

answer

It is not stored in a nested dict
The record is just an object
Some names are already taken
makeRecord checks before it writes
message and asctime are reserved too

basics

~20 s

Each key in the extra mapping becomes an attribute on the LogRecord itself, so a formatter can emit it as a field. Logger.makeRecord raises KeyError if a key collides with an existing record attribute or with message or asctime.

solid answer

~40 s

logger.info("thumbnail written", extra={"job_id": "j-914"}) hands the dict to Logger.makeRecord, which copies every key straight into the record's __dict__ — so it becomes record.job_id, not a nested record.extra. That is what makes stdlib structured logging possible: a formatter can read arbitrary attributes off the record. The guard is deliberate: makeRecord raises KeyError("Attempt to overwrite ...") when the key already exists on the record or is message/asctime, so extra={"module": ...}, {"name": ...}, {"args": ...} or {"process": ...} blow up at the call site rather than silently corrupting the record for every handler. Two practical consequences: namespace your fields, because CPython adds record attributes over time (taskName arrived in 3.12 and instantly reserved that name); and remember extra is per-call, so a %(job_id)s in a shared format string breaks every record that lacks it.

`logger.info("thumbnail written", extra={"job_id": "j-914"})` hands the dict to `Logger.makeRecord`, which copies every key straight into the record's `__dict__` — so it becomes `record.job_id`, not a nested `record.extra`. That is what makes stdlib structured logging possible: a formatter can read arbitrary attributes off the record. The guard is deliberate: `makeRecord` raises `KeyError("Attempt to overwrite ...")` when the key already exists on the record or is `message`/`asctime`, so `extra={"module": ...}`, `{"name": ...}`, `{"args": ...}` or `{"process": ...}` blow up at the call site rather than silently corrupting the record for every handler. Two practical consequences: namespace your fields, because CPython adds record attributes over time (`taskName` arrived in 3.12 and instantly reserved that name); and remember `extra` is per-call, so a `%(job_id)s` in a shared format string breaks every record that lacks it.

code

python · 12 lines

python

import logging, sys

logging.basicConfig(
    stream=sys.stdout, level=logging.INFO, format="%(levelname)s %(job_id)s %(message)s"
)
log = logging.getLogger("thumbnails")
log.info("thumbnail written", extra={"job_id": "j-914"})

try:
    log.info("thumbnail written", extra={"module": "clash"})
except KeyError as exc:
    print("rejected:", exc)

go deeper

for a junior

Know that extra takes a dictionary and that its keys become fields you can print with a %(key)s placeholder. Be ready to say what it is for and to show one call using it.

for a middle

Explain that makeRecord copies the keys into the record's own dict and rejects collisions with a KeyError, and name several reserved attributes such as name, module, args and message.

for a senior

Show how you keep this safe in a running service: namespaced field names, a formatter that discovers attributes instead of a rigid format string, and a rule that no secret or personal datum ever rides in extra.

for a principal

Own the convention. Decide which field names belong to the platform, how a team adds a new one, and treat an unguarded extra key as a schema change that a future interpreter upgrade can turn into a runtime error.

Where `extra` actually goes

Every logger.info(...) call ends up in Logger._log, which asks Logger.makeRecord to build the LogRecord object that handlers will later format. makeRecord takes the extra mapping and copies each key/value pair directly into the new record's instance dictionary — roughly:

python

if extra is not None:
    for key in extra:
        if (key in ["message", "asctime"]) or (key in rv.__dict__):
            raise KeyError("Attempt to overwrite %r in LogRecord" % key)
        rv.__dict__[key] = extra[key]

So extra={"job_id": "j-914"} does not create a nested container; it creates record.job_id. That single line is the whole foundation of structured logging with the standard library: because the record is an ordinary object with an ordinary __dict__, a formatter can walk it and emit whatever fields it finds.

The collision guard, and why it raises

The LogRecord constructor already sets a fixed set of attributes: name, msg, args, levelname, levelno, pathname, filename, module, exc_info, exc_text, stack_info, lineno, funcName, created, msecs, relativeCreated, thread, threadName, processName, process, and — since 3.12 — taskName, which carries the running asyncio task's name. message and asctime are checked explicitly because they do not exist yet at record-creation time: Formatter.format sets record.message from getMessage(), and formatTime sets asctime. Reserving them keeps a caller from poisoning fields the formatting machinery is about to write.

Raising rather than overwriting is the right call. A silent overwrite of record.levelno or record.exc_info would corrupt the record for every handler attached anywhere up the tree, and the failure would surface far from the log call that caused it. A KeyError at the call site is loud and local.

The upgrade hazard is worth stating plainly: this set grows. Code that happily logged extra={"taskName": worker} on 3.11 started raising KeyError on 3.12 at every such call site. Since a logging call is usually inside an except block or a hot loop, that is exactly where you least want a new exception. Namespacing (app_task, or nesting everything under one key such as ctx) makes your fields immune to whatever CPython adds next.

Getting the field into the output

Setting an attribute is only half the job — something must read it. Two consumers exist.

A %-style format string such as "%(job_id)s %(message)s" reads it by name. But a record that lacks job_id then fails to format, and the failure is handled inside Handler.emit, which calls Handler.handleError: a traceback is printed to sys.stderr, that one record is dropped, and the application keeps running (unless logging.raiseExceptions has been set to False, which silences even that). Losing records to a stderr traceback nobody reads is a classic production paper cut, so per-call fields and a rigid format string are a poor pair.

A custom Formatter that discovers attributes is the robust option: it emits whatever fields are present and omits the rest. Alternatively, a Filter can inject a default value for the field onto every record, so the format string always finds it.

When `extra` is the wrong tool: `LoggerAdapter`

For a value that is constant across a scope rather than per call, logging.LoggerAdapter(logger, {"job_id": "j-914"}) binds it once and every call through the adapter carries it. The catch is the default LoggerAdapter.process, which replaces kwargs["extra"] with the adapter's own dict — silently discarding a call-site extra. Python 3.13 added a merge_extra keyword: with merge_extra=True the two dicts are merged and call-site keys win on conflict. Before 3.13 the standard workaround was to override process yourself. The adapter also proxies isEnabledFor, setLevel and the level methods, and adapters can wrap adapters.

Choosing between the three

extra= for facts specific to one event: a duration, a size, an outcome.
LoggerAdapter for facts fixed over an explicit scope you already thread through the code.
A Filter reading a context variable for ambient facts nobody wants to pass at all, such as a request or job id.

Rules that survive review

Namespace field names, or nest them, so a future CPython attribute cannot collide with them.
Keep values JSON-friendly, or make the formatter tolerate them (json.dumps(..., default=str)); a value that fails to serialize costs you the record.
Never put credentials or personal data in extra — structured fields are indexed, retained and widely readable, which is worse than the same secret buried in prose.
Do not assume the field reaches the output; a formatter or format string has to ask for it.

## Where `extra` actually goes Every `logger.info(...)` call ends up in `Logger._log`, which asks `Logger.makeRecord` to build the `LogRecord` object that handlers will later format. `makeRecord` takes the `extra` mapping and copies each key/value pair directly into the new record's instance dictionary — roughly: ```python if extra is not None: for key in extra: if (key in ["message", "asctime"]) or (key in rv.__dict__): raise KeyError("Attempt to overwrite %r in LogRecord" % key) rv.__dict__[key] = extra[key] ``` So `extra={"job_id": "j-914"}` does **not** create a nested container; it creates `record.job_id`. That single line is the whole foundation of structured logging with the standard library: because the record is an ordinary object with an ordinary `__dict__`, a formatter can walk it and emit whatever fields it finds. ## The collision guard, and why it raises The `LogRecord` constructor already sets a fixed set of attributes: `name`, `msg`, `args`, `levelname`, `levelno`, `pathname`, `filename`, `module`, `exc_info`, `exc_text`, `stack_info`, `lineno`, `funcName`, `created`, `msecs`, `relativeCreated`, `thread`, `threadName`, `processName`, `process`, and — since 3.12 — `taskName`, which carries the running asyncio task's name. `message` and `asctime` are checked explicitly because they do not exist yet at record-creation time: `Formatter.format` sets `record.message` from `getMessage()`, and `formatTime` sets `asctime`. Reserving them keeps a caller from poisoning fields the formatting machinery is about to write. Raising rather than overwriting is the right call. A silent overwrite of `record.levelno` or `record.exc_info` would corrupt the record for *every* handler attached anywhere up the tree, and the failure would surface far from the log call that caused it. A `KeyError` at the call site is loud and local. The upgrade hazard is worth stating plainly: this set grows. Code that happily logged `extra={"taskName": worker}` on 3.11 started raising `KeyError` on 3.12 at every such call site. Since a logging call is usually inside an `except` block or a hot loop, that is exactly where you least want a new exception. Namespacing (`app_task`, or nesting everything under one key such as `ctx`) makes your fields immune to whatever CPython adds next. ## Getting the field into the output Setting an attribute is only half the job — something must read it. Two consumers exist. A `%`-style format string such as `"%(job_id)s %(message)s"` reads it by name. But a record that lacks `job_id` then fails to format, and the failure is handled inside `Handler.emit`, which calls `Handler.handleError`: a traceback is printed to `sys.stderr`, that one record is dropped, and the application keeps running (unless `logging.raiseExceptions` has been set to `False`, which silences even that). Losing records to a stderr traceback nobody reads is a classic production paper cut, so per-call fields and a rigid format string are a poor pair. A custom `Formatter` that discovers attributes is the robust option: it emits whatever fields are present and omits the rest. Alternatively, a `Filter` can inject a default value for the field onto every record, so the format string always finds it. ## When `extra` is the wrong tool: `LoggerAdapter` For a value that is constant across a scope rather than per call, `logging.LoggerAdapter(logger, {"job_id": "j-914"})` binds it once and every call through the adapter carries it. The catch is the default `LoggerAdapter.process`, which *replaces* `kwargs["extra"]` with the adapter's own dict — silently discarding a call-site `extra`. Python 3.13 added a `merge_extra` keyword: with `merge_extra=True` the two dicts are merged and call-site keys win on conflict. Before 3.13 the standard workaround was to override `process` yourself. The adapter also proxies `isEnabledFor`, `setLevel` and the level methods, and adapters can wrap adapters. ## Choosing between the three - **`extra=`** for facts specific to one event: a duration, a size, an outcome. - **`LoggerAdapter`** for facts fixed over an explicit scope you already thread through the code. - **A `Filter` reading a context variable** for ambient facts nobody wants to pass at all, such as a request or job id. ## Rules that survive review 1. Namespace field names, or nest them, so a future CPython attribute cannot collide with them. 2. Keep values JSON-friendly, or make the formatter tolerate them (`json.dumps(..., default=str)`); a value that fails to serialize costs you the record. 3. Never put credentials or personal data in `extra` — structured fields are indexed, retained and widely readable, which is worse than the same secret buried in prose. 4. Do not assume the field reaches the output; a formatter or format string has to ask for it.

Without merge_extra, what does logging.LoggerAdapter do with an extra dict passed at the call site?
It throws it away. The default `process` sets `kwargs["extra"] = self.extra`, so the adapter's dict wins wholesale and the per-call fields never reach the record — silently, with no error. On 3.13+ pass `merge_extra=True` and the dicts are merged with call-site keys taking precedence; before that you override `process` and merge by hand.
A format string contains %(job_id)s but a library logs a record without it. What actually happens?
The formatter raises, `Handler.emit` catches it and calls `Handler.handleError`, which prints a traceback to stderr and drops that record. The application does not crash and the log line is simply gone — which is why per-call fields belong in a formatter that reads what is present, or get a default injected by a Filter, rather than in a shared format string.
Does a collision in extra raise even when the message is below the logger's effective level?
No. `Logger.info` checks `isEnabledFor` before it calls `makeRecord`, so a suppressed call never builds the record and never validates the keys. A bad `extra` key can therefore sit dormant in a DEBUG call and raise the day someone turns DEBUG on — a good argument for testing log calls at the level you may need in an incident.

The extra dict is not an envelope stapled to the record — its contents are poured into the record's own pockets, which is why a pocket that is already full makes the call refuse.

saying these in an interview costs you the question

Says extra values live in a separate record.extra dictionary
Believes any key name is safe to pass in extra
Thinks a colliding key just overwrites the record attribute
Assumes extra fields appear in output without a formatter change
Claims extra sticks to the logger for later calls
Puts tokens or personal data in extra because it is not the message

context

open as a page

How do you emit JSON log lines by subclassing logging.Formatter, with no third-party package?

middleshould knowfreq 45%

basics

~20 s

Subclass logging.Formatter and override format(): build a dictionary from the record's attributes, use getMessage() for the interpolated text and formatException for any traceback, then return json.dumps of that dictionary. Install it on a handler with setFormatter.

open as a page

How do you attach a correlation id to every LogRecord using a ContextVar and a logging Filter?

seniorshould knowfreq 40%

basics

~20 s

Keep the id in a contextvars.ContextVar, then add a logging.Filter whose filter() reads it, sets it as an attribute on the record and returns True. Attach that filter to the handler so every record it emits is stamped.

open as a page

How do you govern a structured log-record schema across services, and what does it cost?

principalshould knowfreq 30%

basics

~20 s

Treat the record shape as a data contract: a small stable core of fields, application fields namespaced under one key, machine-friendly UTC timestamps, an explicit rule on secrets, and additive-only changes. The costs are bytes, serialization CPU and human readability.

open as a page

§explore

▾roadmaps that cover this13

§questions

What does logging's extra= dict add to a LogRecord, and when does it raise KeyError?

§ answer

basics

solid answer

code

§ go deeper

▾level notes4 levels

▾deep dive~4 min

Where extra actually goes

The collision guard, and why it raises

Getting the field into the output

When extra is the wrong tool: LoggerAdapter

Choosing between the three

Rules that survive review

▾common follow-ups3 questions

▾analogy~10 s

▾red flags6 flags

§ context

▾related questions5 questions

▾related topics3 topics

How do you emit JSON log lines by subclassing logging.Formatter, with no third-party package?

basics

How do you attach a correlation id to every LogRecord using a ContextVar and a logging Filter?

basics

How do you govern a structured log-record schema across services, and what does it cost?

basics

Where extra actually goes

The collision guard, and why it raises

Getting the field into the output

When extra is the wrong tool: LoggerAdapter

Choosing between the three

Rules that survive review

explore

questions

answer

go deeper

Where `extra` actually goes

When `extra` is the wrong tool: `LoggerAdapter`

context

Where `extra` actually goes

When `extra` is the wrong tool: `LoggerAdapter`