skip to content

Logging Without Leaking

13 roadmaps4 questions

Keeping tokens and user text out of the log, and remembering the logging config is code: a filter that redacts, lazy %-style arguments, and a config channel that will happily execute what it reads.

part ofPythonoverview, primer and where to startread it →
on this pageshow

explore

questions

4

Why pass %s arguments to logging.Logger.info instead of building an f-string?

level: middleimportance: must knowfreq 55%

answer

  1. Ask who does the formatting, and when
  2. A dropped record never pays for it
  3. The values are still separate data
  4. record.args versus a pre-baked record.msg
  5. getMessage runs inside the handler

basics

~20 s

The logging module interpolates %s arguments only when a record is actually emitted, so a filtered-out call costs nothing and the raw values stay on LogRecord.args, where a redaction filter can still rewrite them. An f-string bakes them in first.

solid answer

~40 s

`log.info("route %s served from cache", route_id)` stores the format string on `LogRecord.msg` and the values on `LogRecord.args`; the two are joined only by `LogRecord.getMessage()` inside a handler, after the level check and after every filter has run. Two things follow. First, a call below the effective level, or vetoed by a filter, never formats at all, which matters on a hot path where the argument is an expensive `__str__`. Second, and more important for disclosure, the values are still separate data while filters run, so a redaction filter can inspect and rewrite `record.args`; once an f-string has interpolated a token into `record.msg`, all that is left to redact is a substring of prose. Lazy arguments are not sanitisation, though: an object whose `__str__` leaks still leaks.

code

python · 18 lines
python
import logging


class RedactArgs(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        if record.args:
            record.args = tuple(
                "<redacted>" if str(a).startswith("tok_") else a for a in record.args
            )
        return True


logging.basicConfig(format="%(message)s")
log = logging.getLogger("routing")
log.addFilter(RedactArgs())

log.warning("auth failed for %s", "tok_abc123")   # auth failed for <redacted>
log.warning(f"auth failed for {'tok_abc123'}")    # auth failed for tok_abc123

go deeper

for a junior

Recall the shape: log.info("user %s", name) hands the value to logging as an argument instead of pasting it into the string, and logging joins them itself. Be ready to write a call in that form without hesitating.

for a middle

Explain the mechanics: the record carries msg and args separately, LogRecord.getMessage() interpolates them inside the handler, and the level check happens before any of that. Name what an f-string has already destroyed by then.

for a senior

Show the production judgment: hot paths where a disabled call must cost nothing, and central redaction or structured JSON output that can only work on values that are still separate. Say plainly that lazy arguments are not sanitisation.

for a principal

Own it as a convention, not a preference. Decide the house logging call style, enforce it with a lint rule in CI rather than in review, and be able to explain that a codebase which interpolates at the call site can never be retrofitted with central redaction.

## What the call actually does A logging call such as `log.warning("route %s served from cache", route_id)` does not build a string. `Logger.warning` first asks `isEnabledFor(WARNING)` — roughly a cached integer comparison — and returns immediately if the level is not enabled. If it is, it builds a `LogRecord` whose `msg` attribute is the literal format string `"route %s served from cache"` and whose `args` attribute is the tuple `(route_id,)`. Those two stay separate all the way through `Logger.handle`, through the logger's own filters, through `callHandlers` and each handler's filters and level check, until a `Formatter` finally calls `record.getMessage()`, which does `msg % self.args` only `if self.args`. An f-string inverts that order. `log.warning(f"route {route_id} served from cache")` evaluates the interpolation *at the call site*, before `warning` is even entered, and hands logging a finished string with `args` empty. ## Consequence one: cost you pay for nothing Everything before `getMessage()` can decide the record is not going anywhere. A `DEBUG` line in a route-optimisation job that peaks at 1,200 requests per minute may be disabled in production; with `%s` arguments the cost is a level comparison per call, and the `__str__` of the payload is never invoked. With an f-string you have already built the whole message — including `repr`/`str` of whatever objects it touches — and then thrown it away. The gap is small per call and very visible in a tight loop, which is why most Python linters ship a rule against f-strings in logging calls. ## Consequence two: what a redaction filter can still reach This is the reason the practice belongs to a leaking-logs discussion and not only to a performance one. A redaction filter runs while `msg` and `args` are still distinct. That means it can do structural work: check each element of `record.args`, replace the ones that look like credentials or that came from an untrusted source, and leave the template alone. It can also key on the template itself — the same `record.msg` for every occurrence of an event — to sample, to deduplicate, or to route. Once the value has been interpolated, the filter is reduced to pattern-matching prose. It has to guess which substring of `"route tok_abc123 served from cache"` is the secret, with a regex that is fragile in both directions: it misses formats it was not written for, and it mangles innocent text that resembles one. The same argument applies to structured output. A handler that emits JSON can keep `message` (the template) and the argument values as separate fields only if they arrived separately. An f-string destroys that structure permanently at the call site. ## What lazy arguments do *not* do They are not escaping and not sanitisation. `%s` calls `str()` on the value; if that value is a settings object whose `__repr__` prints an API key, the key is in the output the moment the record is formatted. A newline inside the value is written verbatim, which is a separate injection problem. And if a filter deliberately collapses the record — `record.msg = record.getMessage()` — it must also clear `record.args`, or the next `getMessage()` call tries to interpolate the already-formatted string and can raise or corrupt it. They also do not help when nothing is going to filter the record. If the value is a plain identifier and the level is enabled, an f-string and `%s` produce the same line at almost the same cost. The reason to make `%s` the house style anyway is that you cannot tell, at the call site, whether some future handler, filter or structured sink will want the pieces — and a codebase where half the calls have already interpolated cannot be retrofitted with central redaction. ## The brace-style trap The format used in the *call* is `%`-style and only `%`-style. The `style` argument of `logging.Formatter` selects `%`, `{` or `$` for the *handler's* format string — the one containing `%(message)s` — not for the message you passed. `log.info("user {}", name)` therefore emits the literal `user {}`. If you want brace syntax lazily, pass an object whose `__str__` performs the formatting, and accept that it is a convention your whole codebase has to share.

  • If the record is emitted anyway, does %-style formatting still buy you anything?
    Yes, though not speed. The template stays on record.msg and the values on record.args until the formatter runs, so a redaction filter can rewrite individual arguments structurally rather than regexing prose, a JSON handler can emit template and values as separate fields, and sampling or deduplication can key on the template. Those are the durable benefits; the saved formatting is only a bonus on disabled or filtered calls.
  • Can you use str.format braces in the logging call itself?
    Not by default. LogRecord.getMessage() applies %-interpolation only. The style argument of logging.Formatter chooses %, brace or template syntax for the handler's own format string, not for the message you passed, so log.info("user {}", name) emits the literal braces. To get lazy brace formatting you pass an object whose __str__ does the formatting, and every call site has to use it.
  • Does passing a value as %s keep a secret out of the log file?
    No. %s calls str() on the value when the record is formatted, so a token, or an object whose __repr__ prints one, still reaches the output. Lazy arguments only preserve the opportunity to redact: something has to actually inspect record.args and rewrite it, or the value is emitted verbatim.

An f-string is like sealing a letter before the mailroom sees it; %s arguments hand over the letter and the enclosures separately, so the mailroom can still pull one out.

saying these in an interview costs you the question

  • f-strings are faster, so always prefer them in log calls
  • The level check happens after the message string is built
  • A filter can still recover the separate values from an f-string
  • %s arguments escape or sanitise the value they interpolate
  • %-style is legacy syntax with no runtime difference
  • Only DEBUG calls need lazy arguments

context

resolving links…

open as a page

How do you write a logging.Filter that redacts a token from every LogRecord?

level: middleimportance: should knowfreq 42%

basics

~20 s

Give an object a filter(record) method, or pass any callable taking a LogRecord, rewrite record.msg and record.args in place, and return True to keep the record. Attach it with Handler.addFilter so every record reaching that destination is scrubbed.

open as a page

How can CRLF in user input passed to logging.Logger.info forge a second log entry?

level: seniorimportance: should knowfreq 32%

basics

~20 s

Nothing in the logging module escapes control characters: the value is interpolated into the format string verbatim, so a newline inside it starts what every line-oriented reader treats as a second, attacker-authored entry. Escape untrusted fields before the formatter emits them.

open as a page

Why is logging.config.dictConfig input a trust boundary, and would you ever run logging.config.listen in production?

level: principalimportance: should knowfreq 24%

basics

~20 s

Both apply configuration as code. dictConfig's "()" and "class" keys name dotted paths that it imports and calls at configure time, and listen() applies whatever arrives on a socket. Treat logging configuration as reviewed source, never as data from outside.

open as a page