The bug happened at 3 a.m., and my prints told me nothing

See the problem

Customers say some payments failed overnight. Your payment code has print("charged", amount) in it, so you look for the output.

There isn’t any. The server ran the app in the background, and nothing kept what it printed. Even if it had, each line says “charged 5” with no time, no level, and no hint of which part of the app wrote it. You can’t answer the simplest question: what happened at 3 a.m.?

Define the task

• Input: a function, charge(amount), that refuses amounts of 0 or less.
• Output: a record of each charge and each refusal, with a level: INFO for normal events, WARNING for refusals.
• Rules: each record says which module wrote it. The function doesn’t decide where records go; the program that runs it does.
• The hard part: logging that costs almost nothing when it’s switched off, and can be sent anywhere when it’s on.

Pause and think

⏸ Pause and think

Who should decide where a library’s messages go: the library, or the program using it?

Give it two minutes with pen and paper before you open a hint.

Hints open one at a time:

Hint 1 of 3

print always writes to the screen. logging lets the program choose: a file, a service, or nowhere.

Hint 2 of 3

logging.getLogger(__name__) gives each module its own named logger.

Hint 3 of 3

Write log.info("charged %s", amount), not an f-string, so the text is only built when someone listens.

Understand the idea

logging has three parts:

Part	What it does	Who sets it up
Logger	log = logging.getLogger(__name__). Your code calls log.info(…). Named after the module.	Every module
Level	DEBUG, INFO, WARNING, ERROR, CRITICAL. Messages below the level are dropped.	The program
Handler	Where records go: the screen, a file, a log service. Has a format.	The program, once

Loggers form a tree by name: shop.payments passes its records up to shop, then to the root logger, whose handlers write them out. So a library only creates records, and the program decides, in one place, what to keep and where to send it.

# In main.py only:
logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(name)s: %(message)s")

2026-11-08 03:12:44,051 WARNING shop.payments: refused 0

★Key insight

Each module gets log = logging.getLogger(__name__) and calls log.info("text %s", value). Only the entry point calls basicConfig or adds handlers. Then every record says when, how bad, and where it came from.

Climb the ladder

All three are O(1) per call. What changes is what the records tell you, and who controls them.

Okay

print

The idea: Print each event to the screen.

You see the events while you run it by hand.

def charge(amount: int) -> bool:
    if amount <= 0:
        print("refused", amount)  # no time, no level, and it goes nowhere at 3 a.m.
        return False
    print("charged", amount)
    return True

Time

O(1)

Space

O(1)

Why

One line written per event.

Where it breaks: no time, no level, no source, and you can’t send it to a file or turn it down without editing every line.

Better

The root logger and f-strings

The idea: Call logging.basicConfig at import, then logging.info(f-string).

The waste in Okay: output nobody can filter, route or keep.

Records now have levels, and the program can choose a file.

Highlighted lines are new in this rung.

import logging

logging.basicConfig(level=logging.INFO)  # a library setting up logging for everyone


def charge(amount: int) -> bool:
    if amount <= 0:
        logging.warning(f"refused {amount}")  # the root logger: no module name
        return False
    logging.info(f"charged {amount}")  # the f-string is built even when INFO is off
    return True

Time

O(1)

Space

O(1)

Why

One record per event.

What changed from the previous rung

import logging

logging.basicConfig(level=logging.INFO)  # a library setting up logging for everyone


def charge(amount: int) -> bool:
    if amount <= 0:
        print("refused", amount)  # no time, no level, and it goes nowhere at 3 a.m.
        logging.warning(f"refused {amount}")  # the root logger: no module name
        return False
    print("charged", amount)
    logging.info(f"charged {amount}")  # the f-string is built even when INFO is off
    return True

Where it breaks: every record comes from root, so you can’t tell modules apart or quiet one. The f-string is built even when INFO is off. And basicConfig in a library fights with the program’s own setup.

Best

One logger per module

The idea: log = logging.getLogger(__name__); pass values as arguments; set up handlers only under if __name__ == '__main__'.

The waste in Better: nameless records, set up in the wrong place.

Each record carries the module’s name. log.info("charged %s", amount) stores the template and the value, and builds the text only if a handler keeps the record.

Highlighted lines are new in this rung.

import logging

log = logging.getLogger(__name__)  # one logger per module, named after it


def charge(amount: int) -> bool:
    if amount <= 0:
        log.warning("refused %s", amount)
        return False
    log.info("charged %s", amount)  # the text is only built if someone listens
    return True


if __name__ == "__main__":
    # Only the program's entry point decides where logs go and how they look.
    logging.basicConfig(
        level=logging.INFO, format="%(asctime)s %(levelname)s %(name)s: %(message)s"
    )
    charge(5)

Time

O(1)

Space

O(1)

Why

One record per event, and no text built when it’s dropped.

What changed from the previous rung

import logging

logging.basicConfig(level=logging.INFO)  # a library setting up logging for everyone
log = logging.getLogger(__name__)  # one logger per module, named after it


def charge(amount: int) -> bool:
    if amount <= 0:
        logging.warning(f"refused {amount}")  # the root logger: no module name
        log.warning("refused %s", amount)
        return False
    logging.info(f"charged {amount}")  # the f-string is built even when INFO is off
    log.info("charged %s", amount)  # the text is only built if someone listens
    return True


if __name__ == "__main__":
    # Only the program's entry point decides where logs go and how they look.
    logging.basicConfig(
        level=logging.INFO, format="%(asctime)s %(levelname)s %(name)s: %(message)s"
    )
    charge(5)

When Best isn’t best: big systems log structured data, like JSON with fields, so a log service can search them. Practice 3 builds that.

Write it yourself

Write charge(amount). It returns True and logs INFO charged <amount>, or returns False and logs WARNING refused <amount> for amounts of 0 or less. The tests listen on the root logger and check each record’s logger, level, text and arguments.

Log a charge

Ctrl + Enter runs

import logging def charge(amount): if amount <= 0: print("refused", amount) return False print("charged", amount) return True

Run testsVisualizeReset codeLoads about 6 MB the first time. Best on Wi-Fi.

1. ○Not run yet: charge(5) → True
2. ○Not run yet: charge(-1) → False
3. ○Not run yet: charge(5); charge(0): [not root?, level, text] → [[True, 'INFO', 'charged 5'], [True, 'WARNING', 'refused 0']]
4. ○Not run yet: Extra test

Extra tests check tricky cases. You see their input only if they fail.

Try your own input

Arguments, separated by commas as in Python

charge()Run onceVisualize

Compare

Way	Says when and where	Can be turned down	Text built when off	Use it when
Okay: print	No	No	Yes	Throwaway scripts
Better: root logger, f-strings	Time only	All or nothing	Yes	Never in a library
Best: getLogger(__name__)	Yes	Per module	No	Any code you keep

Common mistakes and edge cases

!basicConfig does nothing the second time

logging.basicConfig() only works if the root logger has no handlers yet. If an imported module already called it, or logged something first, your call is silently ignored. Pass force=True, or better, keep it out of libraries.

• The default level is WARNING, so log.info(…) shows nothing until the program sets INFO.
• log.exception(…) inside except logs at ERROR with the traceback. Outside except, there’s no traceback to add.
• Duplicate lines mean two handlers: often basicConfig plus your own handler, or a handler on a child that also passes records up.
• Don’t log secrets: passwords, tokens and card numbers stay in log files for years.
• print is fine for a command-line tool’s output, the thing the user asked for. Logs are about the program, not for the user.

Say it in the interview

Questions to ask first

• Where do logs end up: a file, the console, a service like CloudWatch or Datadog?
• Do they need to be searchable fields, like JSON, or plain lines?

A 60-second walkthrough

“Each module gets log = logging.getLogger(__name__), so records carry the module name and can be tuned per module, since loggers form a tree by dotted name. I log with arguments, log.info('charged %s', amount), so the string is only built if a handler keeps the record. Levels separate normal events, INFO, from trouble, WARNING and ERROR, and log.exception inside an except attaches the traceback. Only the entry point configures handlers and formats, with basicConfig or dictConfig, so libraries never fight over where logs go.”

Likely follow-ups

• How would you add a request id to every record? A logging.Filter or LoggerAdapter that sets record.request_id, or contextvars with a filter.
• Is logging thread-safe? Yes: handlers take a lock around each write. For many processes, send records to one QueueHandler listener.
• How do you quiet a chatty library? logging.getLogger("urllib3").setLevel(logging.WARNING). Practice 1 is that.

Practice

Three problems, from easy to hard. Each has hints, tests you can run here, and its own Okay, Better and Best answers. Try before you open them.

1. Quiet a chatty library (easy)

A library logs every connection at INFO under the name noisy, and your own INFO messages get lost among them. Write quiet(name) so the library only shows warnings and worse, while your INFO messages still appear.

Hint 1 of 3

logging.disable turns levels off for every logger.

Hint 2 of 3

Setting the root logger’s level changes every logger without its own level, yours included.

Hint 3 of 3

Set the level on that one logger: logging.getLogger(name).setLevel(logging.WARNING).

Quiet a chatty library

Ctrl + Enter runs

import logging def quiet(name): pass

Run testsReset codeLoads about 6 MB the first time. Best on Wi-Fi.

1. ○Not run yet: quiet("noisy"), then your app logs INFO → ['order placed']
2. ○Not run yet: quiet("noisy"), then noisy.http logs INFO → []
3. ○Not run yet: quiet("noisy"), then noisy logs a WARNING → ['retrying']

Try your own input

Arguments, separated by commas as in Python

quiet()Run onceVisualize

Show the Okay, Better and Best answers

Okay

logging.disable

The idea: Turn off INFO everywhere.

The library goes quiet.

import logging


def quiet(name: str) -> None:
    logging.disable(logging.INFO)  # turns off INFO for every logger, yours too

Time

O(1)

Space

O(1)

Why

One setting.

Where it breaks: so does everyone else. Your own INFO messages disappear too.

Better

Raise the root level

The idea: Set the root logger to WARNING.

The waste in Okay: a switch for the whole program.

Highlighted lines are new in this rung.

import logging


def quiet(name: str) -> None:
    logging.getLogger().setLevel(logging.WARNING)  # the root: every logger without its own level

Time

O(1)

Space

O(1)

Why

One setting.

What changed from the previous rung

import logging


def quiet(name: str) -> None:
    logging.disable(logging.INFO)  # turns off INFO for every logger, yours too
    logging.getLogger().setLevel(logging.WARNING)  # the root: every logger without its own level

Where it breaks: loggers without their own level use the root’s, so your app’s INFO is dropped as well.

Best

That logger’s level

The idea: logging.getLogger(name).setLevel(logging.WARNING).

The waste in Better: it quiets the tree from the top, not the one branch.

Children like noisy.http have no level of their own, so they use noisy’s.

Highlighted lines are new in this rung.

import logging


def quiet(name: str) -> None:
    # Loggers form a tree by dotted name, so this also quiets "noisy.http" and the rest.
    logging.getLogger(name).setLevel(logging.WARNING)

Time

O(1)

Space

O(1)

Why

One setting.

What changed from the previous rung

import logging


def quiet(name: str) -> None:
    logging.getLogger().setLevel(logging.WARNING)  # the root: every logger without its own level
    # Loggers form a tree by dotted name, so this also quiets "noisy.http" and the rest.
    logging.getLogger(name).setLevel(logging.WARNING)

When Best isn’t best: in a real app, put these levels in one logging.config.dictConfig at start-up, next to the handlers.

2. Log the error properly (medium)

safe_charge(order_id, charge) calls charge(order_id). If it raises, log at ERROR the message charge failed for <order_id>, with the traceback attached to the record, and return False. Otherwise return True.

Hint 1 of 3

str(e) alone loses which order failed, and where.

Hint 2 of 3

Pasting traceback.format_exc() into the text makes one huge message, and handlers can’t tell it’s an error with a traceback.

Hint 3 of 3

log.exception("charge failed for %s", order_id) inside except does both.

Log the error properly

Ctrl + Enter runs

import logging log = logging.getLogger(__name__) def safe_charge(order_id, charge): charge(order_id) return True

Run testsVisualizeReset codeLoads about 6 MB the first time. Best on Wi-Fi.

1. ○Not run yet: safe_charge("A1", a charge that works) → True
2. ○Not run yet: a charge that raises: [the result, the level] → [False, 'ERROR']
3. ○Not run yet: a charge that raises: the message → 'charge failed for A1'
4. ○Not run yet: Extra test

Extra tests check tricky cases. You see their input only if they fail.

Try your own input

Arguments, separated by commas as in Python

safe_charge()Run onceVisualize

Show the Okay, Better and Best answers

Okay

log.error(str(e))

The idea: Log the error’s message.

The failure is logged, at ERROR.

import logging

log = logging.getLogger(__name__)


def safe_charge(order_id: str, charge) -> bool:
    try:
        charge(order_id)
    except Exception as e:
        log.error(str(e))  # "division by zero": which order? which line?
        return False
    return True

Time

O(1)

Space

O(1)

Why

One record.

Where it breaks: “division by zero” doesn’t say which order or which line.

Better

Paste the traceback in

The idea: log.error(f-string with traceback.format_exc()).

The waste in Okay: it throws away where it failed.

Highlighted lines are new in this rung.

import logging
import traceback

log = logging.getLogger(__name__)


def safe_charge(order_id: str, charge) -> bool:
    try:
        charge(order_id)
    except Exception:
        log.error(f"charge failed for {order_id}\n{traceback.format_exc()}")
        return False
    return True

Time

O(t)

Space

O(t)

Why

Formats the t lines of the traceback into the text.

What changed from the previous rung

import logging
import traceback

log = logging.getLogger(__name__)


def safe_charge(order_id: str, charge) -> bool:
    try:
        charge(order_id)
    except Exception as e:
        log.error(str(e))  # "division by zero": which order? which line?
    except Exception:
        log.error(f"charge failed for {order_id}\n{traceback.format_exc()}")
        return False
    return True

Where it breaks: the traceback is joined into the message, so tools can’t group errors by message or show the traceback on its own.

Best

log.exception

The idea: log.exception(“charge failed for %s”, order_id) inside except.

The waste in Better: it does a handler’s job by hand.

log.exception logs at ERROR and sets record.exc_info, so each handler formats the traceback its own way.

Highlighted lines are new in this rung.

import logging

log = logging.getLogger(__name__)


def safe_charge(order_id: str, charge) -> bool:
    try:
        charge(order_id)
    except Exception:
        # ERROR level, plus the traceback attached to the record as exc_info
        log.exception("charge failed for %s", order_id)
        return False
    return True

Time

O(1)

Space

O(1)

Why

The traceback is attached, and only formatted by a handler.

What changed from the previous rung

import logging
import traceback

log = logging.getLogger(__name__)


def safe_charge(order_id: str, charge) -> bool:
    try:
        charge(order_id)
    except Exception:
        log.error(f"charge failed for {order_id}\n{traceback.format_exc()}")
        # ERROR level, plus the traceback attached to the record as exc_info
        log.exception("charge failed for %s", order_id)
        return False
    return True

When Best isn’t best: if the caller can deal with the error, let it go up instead. Logging it and raising it again logs one failure twice.

3. One JSON object per line (hard)

Log services search fields, not sentences. Write JsonFormatter, a logging.Formatter subclass. Its format(record) returns one line of JSON with level, logger and message. Add error, with the traceback, when the record has one. Messages with quotes, arguments or new lines must still give valid, one-line JSON.

Hint 1 of 3

Building JSON with an f-string breaks on a quote in the message.

Hint 2 of 3

record.msg is the template, like "paid %s". record.getMessage() fills in the arguments.

Hint 3 of 3

self.formatException(record.exc_info) gives the traceback text. json.dumps escapes new lines.

One JSON object per line

Ctrl + Enter runs

import json import logging class JsonFormatter(logging.Formatter): def format(self, record): return ""

Run testsReset codeLoads about 6 MB the first time. Best on Wi-Fi.

1. ○Not run yet: a plain message → 'plain'
2. ○Not run yet: a message with quotes in it → 'he said "hi"'
3. ○Not run yet: log.info("paid %s", "ana") → {'level': 'INFO', 'logger': 'shop', 'message': 'paid ana'}
4. ○Not run yet: Extra test

Extra tests check tricky cases. You see their input only if they fail.

Try your own input

Arguments, separated by commas as in Python

JsonFormatter()Run onceVisualize

Show the Okay, Better and Best answers

Okay

Build the JSON by hand

The idea: An f-string shaped like JSON.

Plain messages come out as valid JSON.

import logging


class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        # Hand-built JSON: a quote in the message breaks it.
        return f'{{"level": "{record.levelname}", "message": "{record.getMessage()}"}}'

Time

O(m)

Space

O(m)

Why

Copies the m characters of the message.

Where it breaks: a quote or a new line in the message makes invalid JSON, and the log service drops the line.

Better

json.dumps of record.msg

The idea: Build a dict and let json.dumps escape it.

The waste in Okay: hand-made escaping.

Highlighted lines are new in this rung.

import json
import logging


class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        return json.dumps(
            {
                "level": record.levelname,
                "logger": record.name,
                "message": record.msg,  # the template, with %s still in it
            }
        )

Time

O(m)

Space

O(m)

Why

Copies the message once.

What changed from the previous rung

import json
import logging


class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        # Hand-built JSON: a quote in the message breaks it.
        return f'{{"level": "{record.levelname}", "message": "{record.getMessage()}"}}'
        return json.dumps(
            {
                "level": record.levelname,
                "logger": record.name,
                "message": record.msg,  # the template, with %s still in it
            }
        )

Where it breaks: record.msg is the template, so the log says “paid %s”. And tracebacks are dropped.

Best

getMessage and formatException

The idea: Use record.getMessage(), and add self.formatException(record.exc_info) when there is one.

The waste in Better: it logs the shape of the message, not the message.

Highlighted lines are new in this rung.

import json
import logging


class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        data = {
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),  # the template with its args filled in
        }
        if record.exc_info:
            data["error"] = self.formatException(record.exc_info)
        return json.dumps(data)  # json.dumps escapes quotes and new lines

Time

O(m + t)

Space

O(m + t)

Why

The message, plus the t characters of any traceback.

What changed from the previous rung

import json
import logging


class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        return json.dumps(
            {
                "level": record.levelname,
                "logger": record.name,
                "message": record.msg,  # the template, with %s still in it
            }
        )
        data = {
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),  # the template with its args filled in
        }
        if record.exc_info:
            data["error"] = self.formatException(record.exc_info)
        return json.dumps(data)  # json.dumps escapes quotes and new lines

When Best isn’t best: add a time, and any extra fields callers pass with extra={…}. Libraries like python-json-logger and structlog do all of it.

Check yourself

A few quick questions. Ones you miss are remembered, so you can find your weak spots later.

1. Predict the outputA fresh program runs only these lines. What appears?

   import logging
   
   log = logging.getLogger("shop")
   log.info("started")
   log.warning("low stock")

   Both linesOnly low stockNothingOnly started

   Check answer
2. Multiple choiceWhich line is best inside a library module?

   logging.info(f"paid {user}")log.info("paid %s", user), with log = logging.getLogger(__name__)print("paid", user)logging.basicConfig(level=logging.INFO)

   Check answer
3. Spot the bugThe log shows "division by zero", but nobody can tell where it happened. What fixes it?

   try:
       charge(order)
   except ZeroDivisionError as e:
       log.error(str(e))

   log.warning(e)log.exception("charge failed for %s", order)print(e)raise e from None

   Check answer
4. Multiple choiceThe urllib3 library floods your log with INFO lines. What quiets only it?

   logging.disable(logging.INFO)logging.getLogger().setLevel(logging.WARNING)logging.getLogger("urllib3").setLevel(logging.WARNING)Delete its handlers

   Check answer

Flashcards

Add these to your review deck. Each card comes back a little later every time you get it right.

• Card 1How should each module get its logger?Show answer
• Card 2Why log.info("x %s", v) and not an f-string?Show answer
• Card 3Who should call logging.basicConfig?Show answer
• Card 4What does log.exception do?Show answer

Add 4 cards to my review deck

Cheat sheet

• log = logging.getLogger(__name__) at the top of each module.
• log.info("paid %s", user): arguments, not f-strings.
• Levels: DEBUG < INFO < WARNING < ERROR < CRITICAL. Default: WARNING.
• log.exception("…") inside except: ERROR plus traceback.
• Set up once, at the entry point: basicConfig(level=…, format=…).
• getLogger("lib").setLevel(logging.WARNING) quiets one library.

Go deeper

• The logging HOWTO, then the cookbook.
• logging.config.dictConfig, for setting it all up in one place.
• Before this: Modules and virtual environments. Next: pytest basics.

Can you do these now?

If you’re not sure of any of these, scroll back to that part before moving on.

• Log with getLogger(__name__) and the right level, instead of print
• Pass values as arguments so messages are only built when someone listens
• Set up handlers and formats once, at the program’s entry point
• Log an error with its traceback using log.exception

✓Mark as completeI already know this

Status: Not started