Logging instead of print

Part of the free LogicWiz Python course, Module 14: Exceptions, context managers and testing. The examples and practice run in the app.

To find a bug, Aarav filled Canteen Counter with print("HERE 1"), print("HERE 2"). Now the bill slips are full of junk, and deleting them all means he loses his clues next time. Real apps use logging: messages you can turn up, down or off.

You'll learn to

• Use the five logging levels and know the default
• Set up logging with `basicConfig`: level, format and stream
• Explain loggers, handlers and formatters
• Decide when to log and when to raise

Learn

Why logging beats print

A log message has a level (how serious it is), a logger name (which part of the app) and a format (time, level, message). You choose, in one place, which levels to show and where they go: the screen, a file, or both.

So you can leave the DEBUG messages in the code forever, hide them in normal use, and switch them on when something breaks. print cannot do any of that.

The five levels

A logger shows messages at or above its level. The default level is WARNING, so info and debug are hidden until you lower it.

Setting it up with `basicConfig`

import logging, sys

logging.basicConfig(
    stream=sys.stdout,
    level=logging.INFO,
    format="%(levelname)s:%(name)s:%(message)s",
    force=True,
)
log = logging.getLogger("canteen")

log.debug("tray 3 weighed 412 g")
log.info("counter opened")
log.warning("only %d samosas left", 3)
log.error("printer offline")

stream=sys.stdout sends logs to normal output (the default is stderr). force=True replaces any earlier setup, because basicConfig otherwise does nothing the second time it is called.

Formats and lazy messages

Useful format fields: %(asctime)s (time), %(levelname)s, %(name)s (logger name), %(message)s, %(funcName)s, %(lineno)d.

Pass values as arguments: log.info("bill %d: Rs %s", 17, total). The text is only built if the message will actually be shown, which is cheaper than an f-string.

To write to a file instead: basicConfig(filename="canteen.log", ...).

Loggers, handlers, formatters

import logging, sys

log = logging.getLogger("canteen.billing")
log.setLevel(logging.DEBUG)
log.handlers.clear()
log.propagate = False

screen = logging.StreamHandler(sys.stdout)
screen.setLevel(logging.INFO)
screen.setFormatter(logging.Formatter("[%(levelname)s] %(name)s - %(message)s"))
log.addHandler(screen)

log.debug("hidden: the handler wants INFO and above")
log.info("bill 101: Rs 85")
log.error("UPI timeout on bill 102")

A logger is what your code calls. It passes each message to its handlers (where it goes: screen, file, email). Each handler has a formatter (how it looks). The logger and each handler both have a level; a message must pass both. Dotted names like canteen.billing form a tree under canteen.

Logging an error with its traceback

import logging, sys

logging.basicConfig(stream=sys.stdout, level=logging.INFO,
                    format="%(levelname)s:%(message)s", force=True)

def split(total, people):
    try:
        return total / people
    except ZeroDivisionError:
        logging.exception("could not split Rs %s", total)
        return None

print(split(100, 0))

logging.exception(...) logs at ERROR level and adds the full traceback. Use it only inside an except block.

Log or raise?

• Raise when the caller must deal with the problem: bad input, a payment that failed. The caller decides what to do.
• Log to record what happened: an order was billed, a retry succeeded, stock is low.
• Do both at the edge of your app: catch the error once at the top, log it with log.exception, and show a friendly message.

Avoid "log and re-raise" at every level: one error then appears five times in the log.

logging.basicConfig(...) only works the first time (unless you pass force=True). If logs are not showing, check two things: the level (default WARNING hides info) and where they go (default stderr).

In one line

Log with levels (DEBUG < INFO < WARNING < ERROR < CRITICAL, default WARNING), set them up once with basicConfig, and raise when the caller must act.

Interview corner

Why use logging instead of print?

Logging gives severity levels you can filter, a consistent format (time, module, level), and handlers that send output to files, the console or remote systems, all configured in one place without editing the code. Debug messages can stay in the code and be switched on when needed.

What are the logging levels, and what is the default?

DEBUG (10), INFO (20), WARNING (30), ERROR (40), CRITICAL (50). The root logger defaults to WARNING, so DEBUG and INFO are hidden until you lower the level, e.g. logging.basicConfig(level=logging.INFO).

What is the difference between a logger, a handler and a formatter?

A logger is the named object your code calls (getLogger("canteen.billing")), with a level and a place in a dotted hierarchy. A handler decides where records go (stream, file, HTTP) and has its own level. A formatter decides how a record looks as text.