PY-L7-13 · Logging Part 1: Levels, Formatters, Handlers

Learning Goals

3 min

By the end of this lesson you can:

Use the five logging levels: DEBUG, INFO, WARNING, ERROR, CRITICAL.
Set up logging with basicConfig and a custom format.
Explain loggers, handlers, and formatters — the three moving parts.
Log exceptions with full tracebacks using logging.exception.

Warm-Up · Why print Fails Automation

5 min

Consider a backup script that ran overnight and "something went wrong." With print you get:

Starting backup
Done
(…or nothing, because the terminal closed and the output vanished)

No timestamps. No severity. No record once the window closes. You can't tell when it ran, whether "Done" meant success, or what the error was.

Today's big idea

logging gives every message a timestamp, a level (how serious), and a destination (screen, file, both) — and you can turn the detail up or down without editing every line. It's the difference between "I think it worked" and "here's exactly what happened, line by line."

New Concept · The Logging System

14 min

The five levels

DEBUG     10  fine-grained detail, for diagnosing problems
INFO      20  normal progress: "started", "processed 40 files"
WARNING   30  something odd, but we carried on  (the default threshold)
ERROR     40  an operation failed
CRITICAL  50  the whole program can't continue

You tag each message with a level. You also set a threshold — messages below it are silently dropped. Set the threshold to DEBUG while developing, INFO in production.

The 30-second setup

import logging

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s  %(levelname)-8s  %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
)

logging.debug("you won't see this — below the INFO threshold")
logging.info("backup started")
logging.warning("disk is 85%% full")
logging.error("could not reach server")

2026-05-28 14:30:01  INFO      backup started
2026-05-28 14:30:01  WARNING   disk is 85% full
2026-05-28 14:30:02  ERROR     could not reach server

Each message now has a timestamp and a level, and DEBUG was filtered out automatically. Change one number (level=logging.DEBUG) and the detail reappears — no editing your log calls.

The three moving parts

Logger — what you call (logging.info(...)). The named entry point for messages.
Handler — where messages go: the console (StreamHandler), a file (FileHandler), email, etc. A logger can have several.
Formatter — how each message looks: timestamp, level, the text.

basicConfig wires up a sensible default of all three. For real apps you create your own logger:

logger = logging.getLogger("backup")    # a named logger for this module
logger.setLevel(logging.DEBUG)
logger.info("using a named logger")

Named loggers let you control different parts of a program independently — "show DEBUG for the network code, INFO for everything else."

Useful format fields

%(asctime)s    timestamp
%(levelname)s  DEBUG/INFO/…
%(name)s       the logger's name
%(message)s    your text
%(filename)s   source file
%(lineno)d     line number

Logging exceptions properly

try:
    risky_operation()
except Exception:
    logging.exception("operation failed")    # logs the message AND the full traceback

logging.exception (call it inside an except block) records your message plus the complete traceback at ERROR level — so you can debug a 3 a.m. failure from the log file alone.

Don't pre-build the string

Prefer logging.info("processed %d files", count) over logging.info(f"processed {count} files"). With the %-style, the string is only built if the message actually gets emitted — a small efficiency win, and the standard idiom.

Worked Example · Instrumenting a File Processor

12 min

Goal: take a script that processes files and add proper logging — so its run leaves a clear, level-tagged story whether it succeeds or fails.

import logging
from pathlib import Path

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s  %(levelname)-8s  %(message)s",
    datefmt="%H:%M:%S",
)
log = logging.getLogger("processor")

def process(folder: str) -> None:
    files = list(Path(folder).glob("*.txt"))
    log.info("starting: %d file(s) in %s", len(files), folder)

    ok, failed = 0, 0
    for f in files:
        log.debug("reading %s", f.name)        # only shown if level=DEBUG
        try:
            text = f.read_text(encoding="utf-8")
            if not text.strip():
                log.warning("%s is empty — skipping", f.name)
                continue
            # …do the real work here…
            ok += 1
        except Exception:
            log.exception("failed to process %s", f.name)
            failed += 1

    log.info("done: %d ok, %d failed", ok, failed)
    if failed:
        log.error("%d file(s) need attention", failed)

process("inbox")

14:30:01  INFO      starting: 5 file(s) in inbox
14:30:01  WARNING   draft.txt is empty — skipping
14:30:01  ERROR     failed to process broken.txt
Traceback (most recent call last):
  ...
UnicodeDecodeError: ...
14:30:01  INFO      done: 3 ok, 1 failed
14:30:01  ERROR     1 file(s) need attention

Read the code

The log reads like a narrative: how many files, which were skipped and why, which failed (with a full traceback thanks to log.exception), and a final tally. Levels do the triage — glance for ERROR/WARNING to find trouble, drop to DEBUG when you need the play-by-play. None of this would survive in a print world once the script ran unattended. Next lesson we send this same stream to a rotating file so it persists forever.

Try It Yourself

13 min

01 🟢 All five levels

Configure logging at DEBUG level and emit one message at each of the five levels. Then change the threshold to WARNING and observe which messages disappear.

02 🟡 Convert prints to logs

Take any script you wrote earlier in this level that uses print and replace each print with the appropriate log level (progress → INFO, problems → WARNING/ERROR). Add a timestamp format.

Hint

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

# print("Created backup")  →
logging.info("created backup %s", path)
# print("Pruned old file") →
logging.info("pruned %s", old.name)

03 🔴 Capture a traceback

Write a function that divides two numbers, call it inside a loop with one zero divisor, and use logging.exception in the except block so the log shows the full traceback for the bad call while the loop continues.

Hint

import logging
logging.basicConfig(level=logging.INFO)

for a, b in [(10, 2), (5, 0), (9, 3)]:
    try:
        logging.info("%d / %d = %s", a, b, a / b)
    except ZeroDivisionError:
        logging.exception("bad division %d / %d", a, b)

Mini-Challenge · A Reusable Logger Factory

8 min

Write get_logger(name, verbose=False) that returns a configured logger writing to the console, at DEBUG level when verbose is true and INFO otherwise, with a format that includes the timestamp, level, and logger name. Make it safe to call twice without adding duplicate handlers.

Show a sample solution

import logging

def get_logger(name: str, verbose: bool = False) -> logging.Logger:
    log = logging.getLogger(name)
    log.setLevel(logging.DEBUG if verbose else logging.INFO)
    if not log.handlers:                 # avoid duplicate handlers
        handler = logging.StreamHandler()
        handler.setFormatter(logging.Formatter(
            "%(asctime)s  %(levelname)-8s  %(name)s  %(message)s",
            datefmt="%H:%M:%S"))
        log.addHandler(handler)
    return log

log = get_logger("app", verbose=True)
log.debug("debug visible because verbose=True")
log.info("hello")

Non-negotiables: level depends on verbose, custom formatter with name, guards against duplicate handlers.

Recap

3 min

Replace print with logging for anything that runs unattended. Tag messages by severity — DEBUG, INFO, WARNING, ERROR, CRITICAL — and set a threshold to control how much you see without editing your code. basicConfig(level=, format=, datefmt=) gets you running in seconds; under the hood, loggers emit, handlers route, and formatters style. Use logging.exception inside except to capture full tracebacks, and the "msg %s", arg form for efficiency. Now your scripts tell you exactly what they did, even at 3 a.m.

Vocabulary Card

log level: The severity tag on a message (DEBUG…CRITICAL); below-threshold ones are dropped.
handler: The destination for log records — console, file, email, etc.
formatter: Defines how each log line looks (timestamp, level, message).
logging.exception: Logs a message plus the current traceback, at ERROR level.

Homework

4 min

Take the disk-usage report from Lesson 6 (or any earlier file-walking script) and fully instrument it with logging: an INFO line when it starts and finishes, DEBUG for each file examined, WARNING for anything unreadable, and a final INFO summary. Add a --verbose flag (argparse) that switches the level between INFO and DEBUG. Confirm the output is readable at both levels.

Sample · instrumented scanner

import argparse, logging
from pathlib import Path

p = argparse.ArgumentParser(description="Disk scan with logging.")
p.add_argument("folder")
p.add_argument("--verbose", action="store_true")
a = p.parse_args()

logging.basicConfig(
    level=logging.DEBUG if a.verbose else logging.INFO,
    format="%(asctime)s  %(levelname)-8s  %(message)s",
    datefmt="%H:%M:%S")
log = logging.getLogger("scan")

log.info("scanning %s", a.folder)
total, count = 0, 0
for f in Path(a.folder).rglob("*"):
    if not f.is_file():
        continue
    try:
        size = f.stat().st_size
        log.debug("%s — %d bytes", f.name, size)
        total += size; count += 1
    except OSError:
        log.warning("could not stat %s", f)

log.info("done: %d files, %.1f MB", count, total / 1e6)

Non-negotiables: start/finish INFO, per-file DEBUG, WARNING on errors, summary, and a working --verbose toggle.

DEBUG 10 fine-grained detail, for diagnosing problems INFO 20 normal progress: "started", "processed 40 files" WARNING 30 something odd, but we carried on (the default threshold) ERROR 40 an operation failed CRITICAL 50 the whole program can't continue

import logging logging.basicConfig( level=logging.INFO, format="%(asctime)s %(levelname)-8s %(message)s", datefmt="%Y-%m-%d %H:%M:%S", ) logging.debug("you won't see this — below the INFO threshold") logging.info("backup started") logging.warning("disk is 85%% full") logging.error("could not reach server")

import logging from pathlib import Path logging.basicConfig( level=logging.INFO, format="%(asctime)s %(levelname)-8s %(message)s", datefmt="%H:%M:%S", ) log = logging.getLogger("processor") def process(folder: str) -> None: files = list(Path(folder).glob("*.txt")) log.info("starting: %d file(s) in %s", len(files), folder) ok, failed = 0, 0 for f in files: log.debug("reading %s", f.name) # only shown if level=DEBUG try: text = f.read_text(encoding="utf-8") if not text.strip(): log.warning("%s is empty — skipping", f.name) continue # …do the real work here… ok += 1 except Exception: log.exception("failed to process %s", f.name) failed += 1 log.info("done: %d ok, %d failed", ok, failed) if failed: log.error("%d file(s) need attention", failed) process("inbox")

14:30:01 INFO starting: 5 file(s) in inbox 14:30:01 WARNING draft.txt is empty — skipping 14:30:01 ERROR failed to process broken.txt Traceback (most recent call last): ... UnicodeDecodeError: ... 14:30:01 INFO done: 3 ok, 1 failed 14:30:01 ERROR 1 file(s) need attention

import logging logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(message)s") # print("Created backup") → logging.info("created backup %s", path) # print("Pruned old file") → logging.info("pruned %s", old.name)

import logging logging.basicConfig(level=logging.INFO) for a, b in [(10, 2), (5, 0), (9, 3)]: try: logging.info("%d / %d = %s", a, b, a / b) except ZeroDivisionError: logging.exception("bad division %d / %d", a, b)

import logging def get_logger(name: str, verbose: bool = False) -> logging.Logger: log = logging.getLogger(name) log.setLevel(logging.DEBUG if verbose else logging.INFO) if not log.handlers: # avoid duplicate handlers handler = logging.StreamHandler() handler.setFormatter(logging.Formatter( "%(asctime)s %(levelname)-8s %(name)s %(message)s", datefmt="%H:%M:%S")) log.addHandler(handler) return log log = get_logger("app", verbose=True) log.debug("debug visible because verbose=True") log.info("hello")