How do you emit JSON log lines by subclassing logging.Formatter, with no third-party package?
answer
- Only one method really matters
- It hangs off the handler, not the logger
- The template is not the message
- Compare against a bare record's attributes
- Give json.dumps a fallback for odd values
basics
~20 sSubclass 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.
solid answer
~40 sA `Formatter` is just an object with a `format(record)` method that returns a string, so returning `json.dumps(...)` instead of an interpolated template is entirely legitimate. The body builds a dict: `record.created` or `self.formatTime(record)` for the timestamp, `record.levelname`, `record.name`, and crucially `record.getMessage()` — `record.msg` is only the template, `getMessage()` applies the `%` arguments. Exceptions need explicit handling: `if record.exc_info: payload["exc"] = self.formatException(record.exc_info)`, and the same for `record.stack_info`. To pick up structured fields, diff `record.__dict__` against the attributes a bare `LogRecord` already carries and emit whatever remains. Serialize defensively with `json.dumps(payload, default=str)` so one unserializable value does not cost you the record. Finally, install it per handler — `handler.setFormatter(...)`; loggers have no formatter — so a console handler can stay human-readable.
code
python · 30 linesimport json, logging, sys
_RESERVED = frozenset(logging.LogRecord("", 0, "", 0, "", None, None).__dict__) | {
"message",
"asctime",
}
class JsonFormatter(logging.Formatter):
def format(self, record):
payload = {
"ts": record.created,
"level": record.levelname,
"logger": record.name,
"msg": record.getMessage(),
}
payload.update(
{k: v for k, v in record.__dict__.items() if k not in _RESERVED}
)
if record.exc_info:
payload["exc"] = self.formatException(record.exc_info)
return json.dumps(payload, default=str)
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(JsonFormatter())
log = logging.getLogger("thumbnails")
log.addHandler(handler)
log.setLevel(logging.INFO)
log.warning("resize slow", extra={"job_id": "j-914", "ms": 8123})go deeper
Know that log output shape is decided by a Formatter attached to a handler, and that you can replace the default one. Being able to describe the goal of one JSON object per line is enough here.
Be ready to write the class: override format, call record.getMessage(), handle exc_info explicitly, and return json.dumps. Explain why record.msg is not the message.
Demonstrate the production details: a defensive default= for serialization, an allow-list or reserved-set diff for fields, no mutation of the shared record, and separate formatters for the human handler and the machine handler.
Frame the formatter as the implementation of a data contract. Decide whether it ships as one internal component every service uses, and how a field is added or removed without breaking the consumers downstream.
## The contract you are implementing `logging.Formatter` looks elaborate but its contract is tiny: `format(record)` returns the string the handler will write. Everything else in the class — `formatMessage`, `formatTime`, `formatException`, `usesTime` — is a helper the default implementation calls. Overriding `format` to build a dict and return `json.dumps(...)` is a completely ordinary use of the class, and it is why structured logging needs no dependency. A formatter lives on a **handler**, not on a logger: `handler.setFormatter(JsonFormatter())`. There is no `Logger.setFormatter`. That placement is a feature — the same record can go to a JSON handler for the collector and a plain-text handler for a developer's terminal, formatted differently by each. ## Reading the record correctly The single most common bug is emitting `record.msg`. `msg` is the *template* exactly as passed; the arguments live separately in `record.args`. `record.getMessage()` is what applies `msg % args` and returns the final text. Use it. A related trap is `record.message`, which does not exist until the default `Formatter.format` sets it — if you override `format` and never call `super().format`, reading `record.message` raises `AttributeError`. Timestamps deserve a decision rather than a default. `record.created` is a float of seconds since the epoch, which is the friendliest thing you can hand a machine: unambiguous, timezone-free, sortable. If you also want a human-readable string, `self.formatTime(record, datefmt)` produces one, but it runs through `Formatter.converter` (`time.localtime` by default) and `time.strftime`, so it inherits the host's timezone and — for codes such as `%c`, `%x` or `%X` — the host's locale. Emitting the epoch value and, if you want text, an explicitly pinned UTC format avoids that whole class of surprise. Errors are not automatic. If the record carries `exc_info`, nothing serializes it for you in an overridden `format`; call `self.formatException(record.exc_info)` to get the traceback text, and `record.stack_info` for a stack dump requested with `stack_info=True`. Note that the default `Formatter.format` caches its result in `record.exc_text` so a second handler need not re-render it; if you call `formatException` directly you skip that cache, which costs a little CPU but keeps you from mutating a record other handlers are about to read. ## Discovering the structured fields A formatter that hardcodes field names cannot emit anything a caller passes in `extra`. The generic trick is to compute the set of attributes a bare record always has, once at import time, and treat everything else as user data: ```python _RESERVED = frozenset(logging.LogRecord("", 0, "", 0, "", None, None).__dict__) ``` Then `{k: v for k, v in record.__dict__.items() if k not in _RESERVED}` is exactly the caller's fields, plus whatever a `Filter` injected. Add `"message"` and `"asctime"` to the reserved set, since the default formatting path may have set them. The alternative — an explicit allow-list of permitted field names — is stricter and is the better choice when the log stream is a contract with a downstream consumer, because it prevents an accidental field from becoming an indexed column. ## Serializing without losing records `json.dumps` raises `TypeError` on anything it does not recognise: a `datetime`, a `set`, a `UUID`, an ORM object someone passed by mistake. Inside a formatter that exception surfaces in `Handler.emit`, which calls `Handler.handleError`, prints a traceback to stderr and **drops the record**. Losing a log line precisely when someone logged an unusual object is a bad trade, so pass `default=str` (or a `default` callable that handles your real types) and keep the record. Two more knobs matter in practice: `ensure_ascii=False` keeps non-ASCII text readable rather than escaping it — valid as long as the handler's stream encoding is UTF-8 — and a compact `separators` argument shaves bytes at volume. And because the output must be one line per record, never emit `indent=...`. ## Discipline around the shared record One record is passed to every handler in turn. A formatter that mutates it — deleting attributes, rewriting `record.msg`, popping fields it considers sensitive — changes what the *other* handlers see, and the resulting bug depends on handler ordering. Enrichment and redaction belong in a `Filter`; a formatter should read and render. ## Cost `json.dumps` is not free, and it runs once per handler per record. That cost is paid only after the level check has passed, so the real lever is level discipline: a DEBUG call that is disabled never builds a record, never runs a filter, and never reaches a formatter. Where the *argument* construction is expensive — summarizing a batch, hashing a payload — guard it with `logger.isEnabledFor(logging.DEBUG)` so you do not pay to build data that is about to be discarded. ## Testing it A JSON formatter is unusually easy to test: format a hand-built `LogRecord` (or capture real ones with `unittest.TestCase.assertLogs`) and assert on `json.loads` of the output. That turns "our log schema" into something a test suite defends rather than something a collector discovers at 3am.
- Why guard an expensive structured payload with logger.isEnabledFor(logging.DEBUG)?Because the arguments are built by the caller before logging can discard them. `logger.debug("batch", extra={"stats": summarise(rows)})` runs `summarise` even when DEBUG is off. `isEnabledFor` consults the effective level and the module-wide disable through a cache, so the guard is cheap. Use it only where building the data actually costs something — for ordinary arguments the level check inside the call is already enough.
- Two handlers share one record and one of them uses your JSON formatter. What can go wrong?Formatting is not isolated: the same `LogRecord` object is handed to each handler in turn, so anything your formatter mutates — deleting an attribute, rewriting `msg`, redacting a field — is visible to the handlers that run after it, and the outcome depends on handler order. The default implementation itself caches `record.exc_text`. Keep formatters read-only and put enrichment or redaction in a Filter.
- How do you keep a traceback from breaking one-line-per-record JSON output?Serialize it as a JSON string value rather than letting it reach the stream raw: `payload["exc"] = self.formatException(record.exc_info)`, then `json.dumps` escapes the embedded newlines. Never pass `indent=` to `json.dumps` in a log formatter, and if the collector prefers structure over text, emit the exception type, string value and frames as separate fields instead of one blob.
saying these in an interview costs you the question
- Emits record.msg and loses the % arguments
- Thinks a formatter is installed on the logger
- Assumes json.dumps can serialize any value
- Reads record.message without calling the base format
- Puts filtering or redaction logic in the formatter
- Pretty-prints JSON so one record spans many lines