PHASE 7Intermediate ~28 min· topic 9 of 12

Topic 7.9

Logging Instead of print

In one line

The logging module records what your program is doing with a severity level, a source name and a format, and can send the records anywhere. It replaces scattered print calls with output you can filter, store and search.

Think of it like this

A ship's logbook. The captain writes down what happened: "08:00 left port", "11:20 storm warning", "14:05 engine failure". Each entry has a time, a severity, and a message, and the book is kept so that after a problem someone can read what led to it. Writing the same things on a scrap of paper that is thrown away at the end of the day (which is what print is) loses the story just when you need it.

Words you'll meet

New words in this topic, in plain English. Come back here whenever one feels fuzzy.

Log record: One logged event: a message plus its level, name and time.
Level: The severity of a record: DEBUG, INFO, WARNING, ERROR, CRITICAL.
Logger: The object you call (logger.info) to create records. Named, and arranged in a tree by dots.
Handler: Sends records to a destination: the screen, a file, a service.
Formatter: Decides how a record looks as text, using a format string.
Root logger: The top logger of the tree. basicConfig configures it.
Propagate: Records from a child logger are also passed up to its parent's handlers.
Structured log: A log line made of fields (often JSON) instead of free text, so it can be searched by field.

Step by step

01Why not print

Both lines below show text, but only the logging one can be told to stay quiet in production, or to go to a file, or to show where it came from. With print you must edit the code to change any of that.

main.pywhole filepython

print("loaded 120 rows")

import logging
logging.warning("loaded %d rows", 120)

02Levels and basicConfig

Without configuration only WARNING and above appear. basicConfig(level=...) lowers the threshold. The format string says how each line looks: the level, the logger name, then the message. It has no time on purpose, so that the output is the same every run. In a real program you would add %(asctime)s. getLogger("shop") makes a logger named shop.

main.pywhole filepython

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s: %(message)s")
logger = logging.getLogger("shop")

logger.debug("cart contents: %s", [1, 2])   # hidden: below INFO
logger.info("order placed")
logger.warning("stock is low")
logger.error("payment failed")

Levels and basicConfigdiagram

Rendering diagram…

03Named loggers form a tree

getLogger("app.db") is a child of getLogger("app"). A record from the child is handled by its own handlers and then passed up to the parents, finally to the root. This is why you configure once at the top of the program and every module just calls getLogger(__name__). This snippet continues after the basicConfig call of the previous step.

main.pywhole filepython

app = logging.getLogger("app")
db = logging.getLogger("app.db")
db.warning("slow query")        # shown with the name app.db
logging.getLogger("app.db").setLevel(logging.ERROR)   # silence just this one

04Log an exception with its traceback

logger.exception(...) is for use inside except. It logs at ERROR level and appends the full traceback, so the log records what print(e) would have lost.

main.pywhole filepython

try:
    int("abc")
except ValueError:
    logger.exception("could not read the quantity")

05Handlers and formatters

A handler picks the destination, and a formatter the look. You can attach several handlers to one logger, for example detailed records to a file and only warnings to the screen. A handler has its own level too. Here only one file handler is attached; the runnable example below adds a second one for the screen.

main.pywhole filepython

logger = logging.getLogger("worker")
logger.setLevel(logging.DEBUG)

file_handler = logging.FileHandler("worker.log", encoding="utf-8")
file_handler.setFormatter(logging.Formatter("%(levelname)s %(message)s"))
logger.addHandler(file_handler)

06Lazy formatting and structured logs

logger.debug("user %s", user) builds the string only when the record will be shown. An f-string would build it every time. For structured logs, make the message a JSON string. Real systems use a formatter that does this for every record.

main.pywhole filepython

import json

logger.info(json.dumps({"event": "order_created", "order_id": 17, "amount": 250}))

Try it yourself

1
Change the threshold
In the first example change INFO to DEBUG, then to ERROR. How many log lines appear each time? Which lines never depend on the level?
2
Add the time
Add %(asctime)s at the start of the format string. The output now contains the time and will change every run. That is why the examples here leave it out, and why real logs include it.
3
Silence a library
In the second example silence the whole app tree with app.setLevel(logging.CRITICAL). Which messages still appear? (The db logger had its own level set, so check that one.)

Code & diagrams

Levels and the threshold New tab

The debug line is hidden. Change level=logging.INFO to logging.DEBUG and run again. Log lines go to the error stream, shown in order with the prints.

Expected output

start
INFO shop: order placed
WARNING shop: stock is low
ERROR shop: payment failed
end

Logger names and where records go New tab

A child logger shares its parent's output. The last line is silenced by raising that logger's own level.

Expected output

app [INFO] starting
app.db [INFO] connected
app.api [WARNING] slow response
app.db [ERROR] connection lost
db parent: app | effective level: INFO

logger.exception keeps the traceback New tab

Compare with print(e), which would show only the message. The log record has the whole traceback.

Expected output

result: 3
ERROR: could not read the quantity 'three'
Traceback (most recent call last):
  File "main.py", line 9, in parse_quantity
    return int(text)
ValueError: invalid literal for int() with base 10: 'three'
result: 0

Two handlers with different levels, and lazy formatting New tab

Everything goes to the file; only warnings go to the screen. The __str__ method shows that the text is built only when needed.

Expected output

(building the text)
screen> queue is long
['DEBUG details: costly value', 'INFO job started', 'WARNING queue is long']

Structured (JSON) log lines New tab

Expected output

{"event": "model_call", "model": "demo-model", "ok": true, "tokens": 412}
{"error": "timeout", "event": "model_call", "model": "demo-model", "ok": false, "tokens": 0}

Log only the slow calls New tab

A service makes thousands of calls, so logging every one drowns the log. Time each call and write a WARNING only when it passes a limit. The fast call is logged at DEBUG, hidden at INFO level. `isEnabledFor` lets you skip costly work when a level is off. (The limit is printed instead of the measured time, so the output is the same on every run.)

Expected output

ok
WARNING llm.client: generate was slow (limit 0.05 s)
ok
debug enabled: True
debug enabled: False

Break it on purpose

Errors are the best teachers. Make each change, read the error, guess what went wrong, then reveal the answer.

Break #1

Misspell a level name

Give basicConfig a level name that does not exist.

main.pywhole filepython

import logging

logging.basicConfig(level="LOUD")
logging.info("hello")

terminal

$ python main.py

── what you'll see ──

Traceback (most recent call last):

File "main.py", line 3, in <module>

logging.basicConfig(level="LOUD")

~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^

File "/lib/python313.zip/logging/__init__.py", line 2118, in basicConfig

root.setLevel(level)

~~~~~~~~~~~~~^^^^^^^

File "/lib/python313.zip/logging/__init__.py", line 1494, in setLevel

self.level = _checkLevel(level)

~~~~~~~~~~~^^^^^^^

File "/lib/python313.zip/logging/__init__.py", line 210, in _checkLevel

raise ValueError("Unknown level: %r" % level)

ValueError: Unknown level: 'LOUD'

Break #2

No configuration: info vanishes

Log at INFO without configuring anything.

main.pywhole filepython

import logging

logging.info("starting up")
logging.warning("disk almost full")

terminal

$ python main.py

── what you'll see ──

WARNING:root:disk almost full

Myth vs fact

Myth

print is good enough for any program.

Fact

For scripts, yes. For anything that runs unattended or has several parts, you need levels, sources and destinations you can change without editing code.

Myth

Logging slows the program down a lot.

Fact

Disabled calls are cheap, especially with lazy %s arguments. Cost grows only with what you actually write out.

Myth

basicConfig can be called again to change the setup.

Fact

It does nothing if the root logger already has handlers. (force=True replaces them.) Configure once, early.

Myth

It is fine to log everything, including user messages and keys.

Fact

Logs travel to many systems and are kept for a long time. Leaving out secrets and personal data is a security and privacy rule, not a style choice.

Pro corner

Extra depth for experienced readers. New to this? Skip it for now and come back later.

▸
Libraries should create their logger with getLogger(__name__) and add only a NullHandler; they never call basicConfig. The application decides the configuration. This is why a well-behaved library is silent until you configure logging.
▸
Use logging.config.dictConfig({...}) to define handlers and formatters in one dictionary, often loaded from YAML or JSON (Topic 7.8). In services, send logs to the standard output and let the platform (Docker, Kubernetes) collect them.
▸
For high-volume services, use QueueHandler and QueueListener so that slow output (disk, network) happens on another thread instead of delaying your request. RotatingFileHandler and TimedRotatingFileHandler stop log files from growing forever.
▸
A correlation id (request id) added to every record lets you follow one request across services. The standard-library contextvars module is the tool that carries such an id through async code, and a logging.Filter can copy it onto each record.
▸
How propagation really works: a record is checked against the level of the logger you called (its effective level, inherited from the nearest ancestor that has one set), and then it is handed to that logger's handlers and every ancestor's handlers. The ancestors' logger levels are not checked again, only each handler's own level. So app.db at INFO still reaches a root handler even if app is set to CRITICAL. Set logger.propagate = False to stop the climb, which is how you avoid the classic duplicate lines when both a logger and the root have a handler.
▸
Lazy formatting defers only the string building, not the arguments. In log.debug("state: %s", expensive_dump()) the function runs every time. Guard it with if log.isEnabledFor(logging.DEBUG):. Calling logger.exception outside an except block logs NoneType: None instead of a traceback, so keep it inside handlers.

Remember this

1
print is fine for learning, but in real programs it has limits. You cannot switch it off without editing code. It has no severity. It does not say where it came from. It goes only to the screen. The logging module fixes all of that. You write logger.info("loaded %s rows", count) once. Then configuration (settings you give the module) decides whether that line is shown, where it goes (screen, file, a log service) and how it looks, without changing your code. Here %s and %d are placeholders: %s is filled with the next argument as text and %d with a whole number.
2
Every log record has a level: DEBUG (10, details for developers), INFO (20, normal progress), WARNING (30, something unexpected but handled), ERROR (40, an operation failed) and CRITICAL (50, the program may not continue). A logger shows only records at or above its threshold (the lowest level it lets through). The default threshold is WARNING, which is why a fresh program prints nothing for info and debug. logging.basicConfig(level=logging.INFO, format="...") sets up the root logger once: the level, the output format, and a handler that writes to the screen.
3
Create named loggers: logger = logging.getLogger(__name__) at the top of each module. __name__ is a name Python fills in with the module's name ("__main__" for the script you run, Topic 6.2). The name shows where a record came from, and names form a tree with dots: app.db is a child of app. Records travel up the tree to the root logger's handlers. So you can configure everything in one place, and still turn a noisy library such as httpx down on its own with logging.getLogger("httpx").setLevel(logging.WARNING).
4
A handler decides where records go (StreamHandler to the screen, FileHandler to a file, RotatingFileHandler to files that rotate when big). A formatter decides how a record looks. Format strings use names like %(levelname)s, %(name)s, %(message)s, %(asctime)s (the time), %(filename)s and %(lineno)d. Real programs put the time and level in every line, so that logs from many machines can be sorted and searched.
5
Pass values as arguments, not pre-built strings: logger.debug("user %s has %d items", name, n), not an f-string. The text is built only if the record is actually going to be shown, so a disabled debug call costs almost nothing. To log a caught exception with its traceback, call logger.exception("what failed") inside the except block. It logs at ERROR level with the traceback. You can also pass exc_info=True to any call. This is the right replacement for the print(e) that throws the traceback away (recall Topic 7.1: except ... as e).
6
Structured logs are the next step. Instead of free text, each line is a small JSON object ({"event": "order_created", "order_id": 17}, Topic 7.7), so a log system can filter by field. Services that call AI models log the model name, token counts, latency and request id this way, so they can find the slow or expensive calls later. Never log secrets or personal data (API keys, passwords, full user messages) unless you have decided to, because logs are copied to many places.

Explain it without notes

Name the five standard log levels in order and explain the default threshold.

Why use logging.getLogger(__name__) in every module rather than the root logger?

Why should you write logger.info("x=%s", x) instead of an f-string?

How do you record a caught exception with its traceback?

Practice

Call logging.basicConfig so that INFO and above appear in the form LEVEL: message (the format string is "%(levelname)s: %(message)s"). Then log one info line and one error line from a logger called pipeline.

Write safe_divide(a, b) that returns a / b. When b is zero it must call logger.exception(...) with a short message and return None. Call it with (6, 3) and with (1, 0).

Make a logger jobs that writes DEBUG and above to a file jobs.log (use a FileHandler and setLevel(logging.DEBUG) on the logger). Log three messages, then read the file and print how many lines it has (it should print 3).

Trade-offs

↔
Verbose versus quiet. DEBUG logs answer questions after a failure, but cost storage and hide important lines in noise. Many teams run INFO in production and raise to DEBUG for a short time when investigating.
↔
Text versus structured logs. Text is easy for people to read on a terminal. JSON lines are easy for machines to filter and aggregate. Many systems print JSON and use a viewer for humans.

Done when you can

Done when you can list the five levels and say which are shown by default.
Done when you can configure logging with basicConfig and a format string.
Done when you can create a named logger and explain how names form a tree.
Done when you can log an exception with its traceback using logger.exception.
Done when you can explain lazy %s formatting and why secrets must not be logged.

Command Palette

Words you'll meet

Step by step

01Why not print

02Levels and basicConfig

03Named loggers form a tree

04Log an exception with its traceback

05Handlers and formatters

06Lazy formatting and structured logs

Try it yourself

Change the threshold

Add the time

Silence a library

Code & diagrams

Break it on purpose

Misspell a level name

No configuration: info vanishes

Myth vs fact

Pro corner

Remember this

Explain it without notes

Practice

Trade-offs

Done when you can