Logging

Interview answer (say this first). Logging is how a running service records what happened in a form a machine can search later: a named logger emits a leveled record, handlers decide where it goes, and formatters decide its shape. In production you log structured fields, never secrets or personal data, and you carry a request or trace ID so one user action can be followed across every service.

Why this exists

To see why logging exists, start with the tool everyone reaches for first: print.

print("user signed in")
print("charge failed", order_id)

print is fine for a scratch script. It is a poor fit for a service, for concrete reasons:

• No level. You cannot say “show me only warnings and errors in production” and “show everything in development.”
• No timestamp or source. When 20 workers write to the same terminal, you cannot tell which line came from where or when.
• No routing. print writes to standard output. You cannot send errors to one place and audit events to another.
• No exception detail. print(err) gives you the message without the traceback, so you lose the line that actually failed.
• No structure. "charge failed order=123 status=timeout" is text. A log system has to guess which part is the order ID. Fields make that exact.
• Not switchable at runtime. You must edit and redeploy code to change what is printed.
• Not thread-safe by design. Interleaved print calls from many threads produce garbled lines.

The logging module, part of the Python standard library, fixes all of this. It gives each message a level, a source name, a timestamp, and a structured record that different destinations can consume.

Note:

The one-sentence purpose. logging turns “what happened” into a leveled, timestamped, structured record that can be filtered, routed, searched, and correlated.

Start from zero

Every word below appears again in this page. Read the table once before continuing.

The five standard levels, from least to most severe, are fixed numbers:

The default level for the root logger is WARNING, which is why a stray logging.info(...) with no configuration seems to disappear.

The core idea

Think of an airport. Planes (events) arrive constantly. There is one tower per runway area (a logger), and the tower decides whether a given plane is worth announcing (the level). The announcement is sent to several speakers: a terminal display, a radio channel, a recording device (the handlers). Each speaker formats the message its own way (the formatter).

The crucial mental model is that the call site and the destination are independent:

Your code says what happened. Configuration decides where it goes and how it looks.

That is what lets you ship the same code to development (debug to console) and production (JSON to a collector) with no code change.

flowchart LR
    A["log.info('user signed in',<br/>extra={'request_id': rid})"] --> B["Logger<br/>app.api"]
    B -->|"enabled for INFO?"| C["LogRecord<br/>msg + level + time + extra"]
    C --> F["Handler: console"]
    F --> H["Formatter<br/>%(asctime)s %(levelname)s %(message)s"]
    C --> G["Handler: JSON file"]
    G --> I["Formatter<br/>{\"ts\":..., \"level\":...}"]
    C --> D{"propagate?"}
    D -->|"yes"| E["ancestor handlers"]

The hierarchy matters because it lets you set one level for a whole subsystem. Set app.db to WARNING and every app.db.* logger becomes quiet, without touching their code.

flowchart TD
    R["root (WARNING)"] --> A["app (INFO)"]
    A --> B["app.api"]
    A --> C["app.db (WARNING)"]
    C --> D["app.db.pool"]
    C --> E["app.db.query"]

app.api has no level of its own, so it inherits INFO from app. app.db.pool inherits WARNING from app.db. That inheritance of the level is the effective level.

How it works

Follow one call, log.info("charged order %s", order_id), step by step.

1. The logger checks the effective level. Logger.info calls isEnabledFor(INFO). If the effective level is WARNING (30), the call stops here and almost nothing is allocated. This is why disabled debug calls are cheap.
2. A LogRecord is built. The message template and arguments are stored separately in the record; the string is not joined yet. The record also gets created (timestamp), name, levelno, pathname, and lineno.
3. Filters run. Any filters attached to the logger or its handlers may drop the record or attach fields such as request_id.
4. The logger passes the record to its own handlers. Each handler checks its own level too, then calls its formatter.
5. The formatter calls record.getMessage(), which performs the % substitution exactly once. Then it applies the format string.
6. The handler emits. A StreamHandler writes to a stream; a FileHandler writes to a file; a QueueHandler puts the record on a queue.
7. If propagate is True (the default), the record is then handed to the logger’s parent, and so on up to the root. Ancestor handlers each get a turn.
8. If propagation reaches the root and no handler anywhere exists, the lastResort handler prints WARNING and above to standard error.

The last point explains a common puzzle: with zero configuration, log.info(...) is silent, but log.warning(...) still prints. The root level filters out the info, and lastResort catches the warning.

Understand one more subtlety: a logger’s own level and a handler’s level are separate gates. A record must pass the logger’s effective level first, then each handler’s level. A common pattern is logger at DEBUG, console handler at INFO, file handler at DEBUG, so the file is complete and the console is quiet. Both gates were verified.

The syntax you will use

Create a logger per module. Never use the root logger directly in library code.

import logging

log = logging.getLogger(__name__)   # name becomes "app.db.pool" in this module

__name__ gives you a hierarchy for free, so you can tune levels by package.

Configure once at startup. basicConfig adds a handler to the root logger. It does nothing on a second call unless you pass force=True.

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(levelname)s %(name)s %(message)s",
)

Levels accept names or constants. Both forms are common.

log.setLevel(logging.DEBUG)
log.setLevel("DEBUG")        # same thing
log.debug("cache hit key=%s", key)

Format fields. These placeholders come from the record, not from your arguments.

"%(asctime)s %(levelname)s %(name)s %(message)s"   # time, level, logger, message
"%(levelname)s %(filename)s:%(lineno)d %(message)s" # level, file, line

Handlers and formatters, wired by hand. This is the explicit version of what basicConfig does.

console = logging.StreamHandler()
console.setLevel(logging.INFO)
console.setFormatter(logging.Formatter("%(levelname)s %(message)s"))

log.addHandler(console)

Log an exception with its traceback. Use log.exception inside an except block.

try:
    charge(order)
except PaymentError:
    log.exception("charge failed order=%s", order.id)   # sets exc_info=True

log.error("msg", exc_info=True) is the explicit form and works outside an except if you pass the sys.exc_info() tuple.

Add structured fields with extra. The keys become attributes the formatter can use.

log.info("user signed in", extra={"request_id": rid, "user_id": user.id})

extra keys must not clash with built-in record attributes such as message, levelname, or msg; a clash raises KeyError.

JSON output. A formatter subclass that serialises selected fields is the usual production shape.

class JsonFormatter(logging.Formatter):
    def format(self, record):
        payload = {"ts": record.created, "level": record.levelname,
                   "logger": record.name, "message": record.getMessage()}
        if hasattr(record, "request_id"):
            payload["request_id"] = record.request_id
        return json.dumps(payload)

Request context with a filter and a ContextVar. This adds the same ID to every line without editing each call.

from contextvars import ContextVar

request_id: ContextVar[str] = ContextVar("request_id", default="-")

class RequestIdFilter(logging.Filter):
    def filter(self, record):
        record.request_id = request_id.get()
        return True

handler.addFilter(RequestIdFilter())

Declarative configuration with dictConfig. Production setups often keep this in a YAML or Python config file.

logging.config.dictConfig({
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {"plain": {"format": "%(levelname)s %(name)s %(message)s"}},
    "handlers": {"console": {"class": "logging.StreamHandler",
                             "formatter": "plain", "level": "INFO"}},
    "loggers": {"app": {"handlers": ["console"], "level": "DEBUG", "propagate": False}},
})

Keep logging off the request path with a queue.

import queue
from logging.handlers import QueueHandler, QueueListener

records = queue.Queue()
listener = QueueListener(records, real_handler)   # runs in its own thread
listener.start()
log.addHandler(QueueHandler(records))   # caller only enqueues, no I/O

Examples: simple to real

Example 1 — replacing print with a level.

import logging

logging.basicConfig(level=logging.INFO,
                    format="%(asctime)s %(levelname)s %(message)s")
log = logging.getLogger(__name__)

log.debug("this is hidden at INFO")   # not printed
log.info("service started")

The debug line costs almost nothing because the level check fails before a record is built. On a typical laptop a disabled call is around 0.08 microseconds and an enabled call around 3 microseconds, so disabled logging is roughly 35 times cheaper.

Example 2 — the logger hierarchy inherits a level.

app = logging.getLogger("app")
app.setLevel(logging.WARNING)
db = logging.getLogger("app.db")

db.info("hidden: effective level is WARNING")
db.warning("shown: warnings pass")
print(db.getEffectiveLevel())     # 30

Setting one level on the parent silences the whole subtree. This is how you quiet a noisy library without editing it.

Example 3 — logging a failure with its traceback.

try:
    total = 1 / 0
except ZeroDivisionError:
    log.exception("checkout total failed")

Output includes ERROR checkout total failed followed by the full traceback ending in ZeroDivisionError: division by zero. Calling log.error("...", exc_info=True) does the same. Calling exc_info=True when no exception is active prints the unhelpful line NoneType: None.

Example 4 — structured logs with a request ID.

import json, logging, contextvars

request_id = contextvars.ContextVar("request_id", default="-")

class JsonFormatter(logging.Formatter):
    def format(self, record):
        return json.dumps({
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
            "request_id": getattr(record, "request_id", request_id.get()),
        })

handler = logging.StreamHandler()
handler.setFormatter(JsonFormatter())
log.addHandler(handler)
log.setLevel(logging.INFO)
log.propagate = False

request_id.set("req-1")
log.info("calling model")

Now the log collector can answer “show every line for request req-1” with a filter on a field, not a regex over free text.

Example 5 — correlate logs with traces through OpenTelemetry.

# pip install opentelemetry-api opentelemetry-sdk opentelemetry-instrumentation-logging
import logging
from opentelemetry.instrumentation.logging import LoggingInstrumentor

LoggingInstrumentor().instrument(set_logging_format=True)

log = logging.getLogger(__name__)
log.setLevel(logging.INFO)
log.propagate = False          # own handler only: do not also emit via the root handler

handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter(
    "%(levelname)s trace_id=%(otelTraceID)s span_id=%(otelSpanID)s %(message)s"))
log.addHandler(handler)

With an active span, a line such as INFO trace_id=1696de8a... span_id=7f820029... calling model is produced.

The instrumentation injects otelTraceID and otelSpanID into every record while a span is active. Inside a span you see a real 32-character trace ID; outside any span both fields are 0. This is what lets you jump from a log line to the exact trace and span in your tracing tool.

Example 6 — the duplicate-handler bug.

logging.basicConfig(level=logging.INFO, format="ROOT %(message)s")
log = logging.getLogger("app")
log.addHandler(logging.StreamHandler())   # own handler
log.setLevel(logging.INFO)
# propagate is True by default, so the root handler runs too
log.info("appears twice")

The line is printed twice: once by the logger’s own handler and once by the root handler it propagates to. Fix it by either not adding a handler to a child logger, or setting log.propagate = False.

In production

• Never log secrets, tokens, passwords, or API keys. Log presence, not value: log.info("api_key_configured=%s", bool(key)). A leaked key in a log index is a credential leak.
• Never log raw prompts, completions, or user messages by default. They contain personal data (PII), and in agent systems they may contain tool outputs and retrieved documents. Log lengths, model name, token counts, and a hashed conversation ID instead.
• Log exceptions with log.exception or exc_info=True. log.error(str(err)) throws away the traceback, which is the part that tells you the failing line. Use the message for context and the traceback for the diagnosis.
• Log once, at the layer that handles or translates the error. Logging and re-raising at every layer turns one failure into five identical lines and makes the real cause harder to find.
• Use lazy %s formatting, not f-strings. log.debug("payload=%s", obj) defers str(obj) until the record is actually emitted; log.debug(f"payload={obj}") calls str(obj) even when DEBUG is off. In a hot loop that difference is measurable.
• Guard genuinely expensive arguments. %s still evaluates its arguments. If building the value is costly, check first: if log.isEnabledFor(logging.DEBUG): log.debug("...", build_report()).
• Keep logging off the critical path for slow handlers. A file or network handler writes synchronously in the calling thread. Under load, a slow log sink becomes an outage. Use QueueHandler plus QueueListener, or a well-configured aggregator agent.
• Cap the growth of log sinks. A runaway DEBUG loop can fill a disk and crash the host. Use RotatingFileHandler (or its timed variant) locally, and a retention policy in the aggregator.
• Use UTC timestamps and a consistent field schema. Mixed time zones and renamed fields make cross-service queries impossible. Pick field names once, document them, and keep them stable.
• Configure logging in one place. Per-module basicConfig calls are a no-op after the first, so half the service ends up with no handler. Configure once at startup, ideally with dictConfig.
• Watch for duplicate records in containers and libraries. A library that adds its own handler plus propagation produces the double-line bug above. Set propagate = False on loggers that own handlers.
• Pin down sampling for high-volume events. Logging every token of every LLM stream is both slow and expensive. Log one summary line per request and sample the rest.

Interview questions

1. Why not just use print?

Answer. print has no level, no timestamp, no source name, no structure, and no routing, and it always writes to standard output. logging adds all of these, so the same event can be filtered by severity, sent to several sinks, formatted as JSON, and searched by field. print also cannot attach a traceback the way log.exception does.

Follow-up: “When is print still acceptable?” In short-lived scripts, CLI tools, and one-off debugging where the output is for a human sitting at the terminal and will never be aggregated.

Trap. Saying logging is only for saving to files. Its real value in production is structured, searchable records plus runtime control of verbosity.

2. How does the logger hierarchy work?

Answer. Loggers form a tree by dotted name: app.db.pool is a child of app.db, which is a child of app. A logger with no level of its own uses the effective level of its nearest configured ancestor, and by default records propagate up to ancestors’ handlers. So one setLevel on app controls the whole app.* subtree.

Follow-up: “What happens with no configuration at all?” The root level is WARNING, so INFO and below are dropped, and a lastResort handler prints WARNING and above to standard error.

Trap. Believing each logger has an independent level. A logger created with getLogger("x") has level NOTSET (0) until you set it or inherit one.

3. What is the difference between a logger’s level and a handler’s level?

Answer. They are two gates. The logger’s effective level decides whether a record is created at all. Each handler’s level then decides whether that handler emits it. Setting the logger to DEBUG and the console handler to INFO gives you a full debug file and a quiet console.

Follow-up: “How is a helper library silenced?” Set its logger to WARNING, for example logging.getLogger("urllib3").setLevel(logging.WARNING), or set propagate = False if it adds its own handler.

Trap. Thinking the handler level can make a record pass the logger level. It cannot. A record the logger dropped never reaches any handler.

4. How do you log an exception with a traceback?

Answer. Call log.exception("context message") inside an except block. It logs at ERROR and sets exc_info=True automatically. log.error("context", exc_info=True) is equivalent, and you can pass a saved sys.exc_info() tuple to log a traceback after the except block has ended.

Follow-up: “What does exc_info=True do outside an except?” Nothing useful: the record has no exception, and most formatters print NoneType: None.

Trap. Using log.error(str(err)). You keep the message but lose the traceback and exception type, which is usually the only thing that identifies the failing line.

5. What is structured logging and why does it matter?

Answer. Structured logging emits fields rather than a sentence, usually as JSON, for example {"level":"ERROR","request_id":"r-1","order_id":123,"message":"charge failed"}. A log system can filter and aggregate on order_id or request_id directly, without fragile regular expressions. It also makes logs consistent across services written in different languages.

Follow-up: “What is the cost?” JSON is larger on disk and less pleasant to read in a raw terminal, so teams often use JSON in production and a human format in development.

Trap. Adding free-text fields with changing names. Structure only helps if the field names are stable and documented.

6. How do you correlate logs for one request across services?

Answer. Generate a correlation ID at the edge, put it in a ContextVar or a LoggerAdapter, add it to every record through a filter, and pass it to downstream services in a header such as X-Request-ID. If you already use OpenTelemetry, the active span’s trace_id is the same idea and can be injected into logs automatically, so logs and traces share one key.

Follow-up: “Why not just use the user ID?” A user can have many concurrent requests, and some requests have no user. A per-request ID separates them, and it is safe to log because it is generated, not personal.

Trap. Relying on timestamps to group a request’s lines. Concurrent requests interleave, and clock skew between hosts breaks the assumption.

7. What should you never log?

Answer. Secrets and credentials (passwords, tokens, API keys, session cookies), personal data (emails, phone numbers, addresses, full payment details), and raw prompts or model outputs unless you have an explicit, reviewed reason. These values leak into log indices, backups, and support tickets, and they are very hard to remove later.

Follow-up: “How do you debug model behaviour if you cannot log prompts?” Log metadata: model name, prompt template version, token counts, latency, finish reason, and a hash or internal ID for the conversation. Capture full content only in a separately controlled store with access limits and retention.

Trap. Thinking a private log index makes it safe. Access is usually broad, retention is long, and a breach exposes everything.

8. Is logging expensive, and how do you keep it cheap?

Answer. A disabled call is very cheap because the level check fails before a record is built. An enabled call costs a few microseconds plus the handler’s work, and a slow file or network handler can dominate. Keep it cheap by using lazy %s formatting, guarding expensive argument construction with isEnabledFor, logging summaries instead of loops, and moving slow sinks off the request path with QueueHandler.

Follow-up: “How would you prove a logging change helped?” Profile the request under realistic load, or measure calls per second before and after, rather than guessing.

Trap. Believing f-strings and %s are the same because both end up in the message. The f-string formats eagerly, even when the level is disabled, so it pays the cost for nothing.

Remember this

• print describes; logging records. Levels, timestamps, sources, structure, and routing are the reason it exists.
• A logger is a named channel; handlers are destinations; formatters are shapes. Configure them once at startup.
• Levels are two gates: the logger decides whether a record exists, each handler decides whether it is emitted.
• Structured fields plus a request or trace ID turn logs from prose into something you can query and correlate.
• Never log secrets, PII, or raw prompts, and prefer lazy %s formatting over eager f-strings.