Logging and Observability
Logging and Observability
The boring default is the logging module: named loggers, levels, and a format you set once. print is for programs whose whole job is to print. Production desks log.
Mental model
A logger has a name ("desk", "desk.tickets"). A level filters: DEBUG, INFO, WARNING, ERROR, CRITICAL. A handler writes records (usually stderr or a file). A formatter turns a record into a line.
logging.getLogger("desk") is the same logger everywhere in the process. Configure it at the edge (main), not inside library functions.
Observability here means: you can tell what the process did after the fact without attaching a debugger. Levels and a stable format get you most of that. Traces and metrics are extra tools; they are not a reason to skip logs.
Worked examples
Case 1: basicConfig and a named logger
Save as desk_log.py. Set the format once. Log on the named logger, not the root, so you can turn desk up or down later.
# desk_log.py
import logging
import sys
logging.basicConfig(
level=logging.INFO,
format="%(levelname)s %(name)s: %(message)s",
stream=sys.stdout,
)
log = logging.getLogger("desk")
def main() -> None:
log.info("shift opened")
log.warning("table 0 is invalid")
if __name__ == "__main__":
main()Run:
uv run python desk_log.pyOutput:
INFO desk: shift opened
WARNING desk: table 0 is invalid
stream=sys.stdout is for this book’s captured output. At work, the default stderr is fine.
Case 2: Child loggers keep the tree
Save as ticket_log.py. desk.tickets inherits the parent’s level unless you change it.
# ticket_log.py
import logging
import sys
logging.basicConfig(
level=logging.INFO,
format="%(levelname)s %(name)s: %(message)s",
stream=sys.stdout,
)
log = logging.getLogger("desk.tickets")
def open_ticket(ticket_id: int, table: int) -> None:
log.info("opened ticket %s at table %s", ticket_id, table)
def main() -> None:
open_ticket(7, 12)
log.debug("not printed at INFO")
if __name__ == "__main__":
main()Run:
uv run python ticket_log.pyOutput:
INFO desk.tickets: opened ticket 7 at table 12
The debug line is silent. %s lazy-formats only if the line is emitted.
Case 3: JSON-ish lines
Save as json_log.py. A custom Formatter is enough for log processors that want one object per line. You do not need a framework for this.
# json_log.py
import json
import logging
import sys
class JsonIshFormatter(logging.Formatter):
def format(self, record: logging.LogRecord) -> str:
return json.dumps(
{
"level": record.levelname,
"logger": record.name,
"msg": record.getMessage(),
}
)
def main() -> None:
log = logging.getLogger("desk")
log.setLevel(logging.INFO)
log.handlers.clear()
log.propagate = False
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(JsonIshFormatter())
log.addHandler(handler)
log.info("shift opened")
log.warning("table 0 is invalid")
if __name__ == "__main__":
main()Run:
uv run python json_log.pyOutput:
{"level": "INFO", "logger": "desk", "msg": "shift opened"}
{"level": "WARNING", "logger": "desk", "msg": "table 0 is invalid"}
propagate = False stops a second copy on the root logger.
Case 4: Exceptions belong in the log
Save as log_exception.py. log.exception records the traceback at ERROR after you catch.
# log_exception.py
import logging
import sys
logging.basicConfig(
level=logging.INFO,
format="%(levelname)s %(name)s: %(message)s",
stream=sys.stdout,
)
log = logging.getLogger("desk")
def open_table(n: int) -> None:
if n <= 0:
raise ValueError(f"table {n}: number must be positive")
def main() -> None:
try:
open_table(0)
except ValueError:
log.exception("could not open table")
print("handled")
if __name__ == "__main__":
main()Run:
uv run python log_exception.pyOutput:
ERROR desk: could not open table
Traceback (most recent call last):
File "log_exception.py", line 20, in main
open_table(0)
~~~~~~~~~~^^^
File "log_exception.py", line 15, in open_table
raise ValueError(f"table {n}: number must be positive")
ValueError: table 0: number must be positive
handled
The process exits zero because the exception was caught. Line numbers follow the file you saved.
The trap
print looks like logging until you need a level, a name, or a file.
Save as print_as_log.py:
# print_as_log.py
def main() -> None:
print("shift opened")
print("table 0 is invalid")
if __name__ == "__main__":
main()Run:
uv run python print_as_log.pyOutput:
shift opened
table 0 is invalid
There is no WARNING, no logger name, and no way to silence it in production without editing the function. Case 1 is the fix. Keep print for CLIs that write the user’s answer to stdout.
The boring rule
getLogger(__name__)in library modules. Configure handlers inmain.- Log with
%s(or{style if you set it), notf"..."built before the level check unless the string is cheap. log.exceptioninexceptblocks you handle.- One format for the process. JSON-ish if a collector wants objects; otherwise the
basicConfigline format. - Do not log secrets (API keys, raw card numbers).
Try this
- In
desk_log.py, addlog.debug("checking tables")and rerun atINFO, then setlevel=logging.DEBUG. - In
ticket_log.py, log anerrorwhentable <= 0. - In
json_log.py, add"ticket": 7only when the message is about a ticket (passextra=or put it in the message).