8.1 Logging Fundamentals
print() shows something happened; it can't say how serious it was, can't be turned
down in production without editing code, and can't be redirected to a file/monitoring
system without wrapping every call. The logging module (stdlib) fixes all three:
print() |
logging |
|---|---|
| always shown, no severity | each message has a level (8.2) — filter by importance |
| output hard-coded to stdout | routed to console, file, or both, without touching call sites |
| no built-in timestamp / source info | can auto-include time, module, line number, level |
| always on | can be turned off/down for whole modules without deleting the calls |
Uses of logging: diagnosing problems in code that's already running (production,
someone else's machine) where attaching a debugger isn't an option; leaving a permanent,
timestamped record (audit trail) of what a program did; separating "routine detail"
(DEBUG) from "something is actually wrong" (ERROR) so the two don't drown each other
out.
import logging
# straight out of the box, with zero configuration:
logging.debug("debug msg") # (nothing printed)
logging.info("info msg") # (nothing printed)
logging.warning("warning msg") # WARNING:root:warning msg
logging.error("error msg") # ERROR:root:error msg
logging.critical("critical msg") # CRITICAL:root:critical msg
WARNING:root:warning msg ERROR:root:error msg CRITICAL:root:critical msg
Note: that root in the output above is not "no logger" — it's the name of
an actual, implicit default Logger object. Every call to a module-level function like
logging.debug() or logging.warning() is really logging.getLogger("root").debug() /
.warning() under the hood (the first such call also silently runs basicConfig() for
you, which is why a handler and format appeared with zero setup).
8.2 Loggers, Handlers, Formatters and Levels
Three cooperating pieces do the work:
| Piece | Job |
|---|---|
| Logger | the object your code calls (logger.info(...)) — decides whether a message is important enough to go anywhere at all |
| Handler | decides where an accepted message goes — console, a file, both |
| Formatter | decides what the message looks like — plain text, with a timestamp, etc. |
Log levels — every message has a severity, and every logger/handler has a threshold; a message is only emitted if its level is at or above that threshold:
| Level | Numeric value | Meaning |
|---|---|---|
DEBUG |
10 | fine-grained detail, useful only while diagnosing something |
INFO |
20 | confirmation that things are working as expected |
WARNING |
30 | something unexpected, but the program can keep going — the default level |
ERROR |
40 | a real problem — some functionality failed |
CRITICAL |
50 | a severe error — the program itself may be unable to continue |
The default level is WARNING — that's exactly why debug() and info() printed
nothing in the previous demo: they're below the root logger's default threshold.
import logging
print(logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)
# 10 20 30 40 50
print(logging.getLevelName(logging.getLogger().getEffectiveLevel()))
# WARNING -> confirms the root logger's default threshold
10 20 30 40 50 WARNING
Every later example in this chapter configures things through basicConfig() (8.3),
which builds a handler and formatter behind the scenes. Building them by hand once,
here, makes the wiring from the table above concrete: a Handler decides where
output goes, a Formatter decides what it looks like, and addHandler() is what
actually attaches one to a logger.
import logging
demo_logger = logging.getLogger("demo.handler_example")
demo_logger.setLevel(logging.DEBUG)
demo_logger.propagate = False # keep this demo isolated from the root logger's own handler
handler = logging.StreamHandler() # writes to sys.stderr by default
formatter = logging.Formatter("%(levelname)s | %(name)s | %(message)s")
handler.setFormatter(formatter)
demo_logger.addHandler(handler)
demo_logger.debug("built by hand, no basicConfig involved")
# DEBUG | demo.handler_example | built by hand, no basicConfig involved
DEBUG | demo.handler_example | built by hand, no basicConfig involved
In practice — structured JSON logging. A production service typically swaps the
plain-text Formatter above for one that emits JSON ({"level": "ERROR", "request_id":
"abc123", "user_id": 42, "message": "..."}) so a log-aggregation platform like the ELK
stack, Datadog, or Splunk can index and alert on individual fields — searching "every
ERROR for user 42" only works if the logs are structured data, not free text.
8.3 Logging Configuration
Implementing logging in a module always starts the same way — get a logger named
after the current module, then log through it instead of the bare logging.*
functions used above (those actually go through a hidden shared "root" logger):
import logging
logger = logging.getLogger(__name__) # named after this module — "__main__" here
print(logger.name) # __main__
logger.warning("module-level logger still uses the same default WARNING threshold")
# WARNING:__main__:module-level logger still uses the same default WARNING threshold
__main__
Logging an exception is the single most common real-world logging call: inside an
except block, logger.exception(msg) logs at ERROR level and automatically
attaches the full traceback of the exception currently being handled — no need to
format it yourself. It's exactly equivalent to
logger.error(msg, exc_info=True), spelled more conveniently.
def divide(a, b):
return a / b
try:
divide(10, 0)
except ZeroDivisionError:
logger.exception("division failed") # reuses the `logger` object from the cell above
# ERROR:__main__:division failed
# Traceback (most recent call last):
# ...
# File "...", line ..., in divide
# return a / b
# ZeroDivisionError: division by zero
# equivalent, spelled out explicitly:
# logger.error("division failed", exc_info=True)
In practice — this is exactly what Sentry (and similar error-tracking tools) hook
into. An error-monitoring integration attaches itself to the logging module so that
every logger.exception() call — like the one above — is automatically captured,
grouped with similar errors, and used to page an on-call engineer, all without the
application code knowing the monitoring tool exists.
logging.basicConfig() is the quick way to configure the root logger in one call —
set the threshold level and the message format without manually wiring up a handler and
formatter. It only has an effect once per process: later calls are ignored unless
force=True is passed:
import logging
logging.basicConfig(level=logging.DEBUG, format="%(levelname)s %(name)s: %(message)s")
logger = logging.getLogger(__name__)
logger.debug("now visible, threshold lowered to DEBUG")
# DEBUG __main__: now visible, threshold lowered to DEBUG
logging.basicConfig(level=logging.CRITICAL) # ignored -> root logger is already configured
logger.debug("still visible, second basicConfig call was a no-op")
# DEBUG __main__: still visible, second basicConfig call was a no-op
logging.basicConfig(level=logging.CRITICAL, force=True) # force=True actually reconfigures
logger.debug("this one is now suppressed") # (nothing printed)
logger.critical("only CRITICAL gets through now") # CRITICAL:__main__:only CRITICAL gets through now
CRITICAL:__main__:only CRITICAL gets through now
Logging to a file — pass filename to basicConfig() and messages go there instead
of the console. filemode controls what happens to any content already in that file:
filemode |
Behavior |
|---|---|
"a" (default) |
append — new runs add on to the end, old log history is kept |
"w" |
overwrite — the file is truncated at the start of each run, only this run's messages remain |
(force=True is needed below only because basicConfig was already called earlier in
this notebook session — a fresh script wouldn't need it.)
import logging, tempfile, os
log_path = tempfile.mktemp(suffix=".log")
logging.basicConfig(filename=log_path, filemode="a", level=logging.INFO,
format="%(levelname)s: %(message)s", force=True)
logging.getLogger(__name__).info("first run")
logging.basicConfig(filename=log_path, filemode="a", level=logging.INFO,
format="%(levelname)s: %(message)s", force=True)
logging.getLogger(__name__).info("second run, still appended")
with open(log_path) as f:
print(f.read())
# INFO: first run
# INFO: second run, still appended
logging.basicConfig(filename=log_path, filemode="w", level=logging.INFO,
format="%(levelname)s: %(message)s", force=True)
logging.getLogger(__name__).info("third run, file was truncated first")
with open(log_path) as f:
print(f.read()) # INFO: third run, file was truncated first -> the earlier two lines are gone
os.remove(log_path)
INFO: first run INFO: second run, still appended INFO: third run, file was truncated first
Going deeper — duplicate log lines and propagate. By default a logger doesn't just
hand a record to its own handlers — it also passes the record up to its parent
logger's handlers, and so on up to the root logger (this is propagate, True by
default). That's harmless as long as only one logger in the chain has handlers. But if a
module logger has its own handler and the root logger also has one (e.g. from
basicConfig(), or from the addHandler() demo in 8.2), the same message gets emitted
once per handler it reaches — the classic "why is everything printed twice" bug. The
fix is logger.propagate = False on the logger that shouldn't also report to its
parent.
import logging
logging.basicConfig(level=logging.INFO, format="%(levelname)s:%(name)s:%(message)s", force=True)
dup_logger = logging.getLogger("app.duplicate_demo")
dup_logger.setLevel(logging.INFO)
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("%(levelname)s:%(name)s:%(message)s"))
dup_logger.addHandler(handler) # a *second* handler, in addition to root's own
dup_logger.info("one call...")
# INFO:app.duplicate_demo:one call... <- from dup_logger's own handler
# INFO:app.duplicate_demo:one call... <- from root's handler, via propagation
dup_logger.propagate = False # stop it from also reaching the root logger's handler
dup_logger.info("...now printed only once")
# INFO:app.duplicate_demo:...now printed only once
INFO:app.duplicate_demo:one call... INFO:app.duplicate_demo:one call... INFO:app.duplicate_demo:...now printed only once
In practice — a real, commonly-hit bug in microservices. A shared internal library
that calls logging.basicConfig() (or otherwise attaches its own handler) on import,
inside an application that has already configured its own root logger, produces exactly
this duplicate-log-lines symptom in production — a frequent enough gotcha that many
library style guides explicitly forbid a library from configuring logging itself,
leaving that entirely to the application.
8.4 Debugging Approaches
When something's wrong, there are a few standard ways to find out why, roughly from least to most effort:
| Approach | How | Best for |
|---|---|---|
| Print debugging | sprinkle print() at suspect points |
a quick, throwaway check on a small script |
| Logging | logging calls with levels (8.1–8.3) |
anything that needs to stay in the codebase, or runs where no one is watching live |
| Assertions | assert on invariants that must hold (8.6) |
catching a corrupted state immediately, at its source, instead of downstream |
Interactive debugger (pdb, 8.5) |
pause execution and inspect/step through live state | when the bug depends on state that's too complex to guess from print output alone |
None of these is strictly better — print debugging is fine for a five-line script;
reaching for pdb to debug a five-line script is overkill, while reaching for print()
in a bug that depends on deeply nested object state usually just produces more
confusion, not less.
8.5 pdb and Interactive Debugging
pdb is Python's built-in interactive debugger. Dropping breakpoint() (shorthand for
import pdb; pdb.set_trace()) into a line of code pauses execution right
there and opens a (Pdb) prompt where you can inspect and step through the live
program state:
| Command | Effect |
|---|---|
l (list) |
show the source code around the current line |
p <expr> (print) |
evaluate and print an expression in the current scope |
n (next) |
run the current line, stop at the next one (steps over function calls) |
s (step) |
like n, but steps into a function call instead of over it |
c (continue) |
resume normal execution until the next breakpoint (or the program ends) |
w (where) |
show the current call stack |
q (quit) |
abort the debugging session entirely |
A real session waits for you to type these at a terminal. The cell below reproduces one
exactly by feeding it a fixed sequence of commands as input, so the transcript below is
what actually typing l, p a, p b, p total, n, c at the (Pdb) prompt
produces:
Walking the transcript below: l lists the source around the paused line; p a →
2, p b → 3, p total → 5 (line 2, total = a + b, already ran before the
breakpoint paused execution at line 4); n steps to the return total line; c
resumes execution to completion, and the script's own print(buggy_add(2, 3)) prints
the final 5.
import subprocess, tempfile, os
script = (
"def buggy_add(a, b):\n"
" total = a + b\n"
" breakpoint()\n"
" return total\n"
"\n"
"print(buggy_add(2, 3))\n"
)
with tempfile.NamedTemporaryFile("w", suffix=".py", delete=False) as f:
f.write(script)
script_path = f.name
commands = "l\np a\np b\np total\nn\nc\n" # what you'd type at each (Pdb) prompt
result = subprocess.run(["python3", script_path], input=commands, capture_output=True, text=True)
print(result.stdout.replace(script_path, "buggy_add.py"))
os.remove(script_path)
# > buggy_add.py(4)buggy_add()
# -> return total
# (Pdb) 1 def buggy_add(a, b):
# 2 total = a + b
# 3 breakpoint()
# 4 -> return total
# 5
# 6 print(buggy_add(2, 3))
# [EOF]
# (Pdb) 2
# (Pdb) 3
# (Pdb) 5
# (Pdb) --Return--
# > buggy_add.py(4)buggy_add()->5
# -> return total
# (Pdb) 5
> buggy_add.py(4)buggy_add() -> return total (Pdb) 1 def buggy_add(a, b): 2 total = a + b 3 breakpoint() 4 -> return total 5 6 print(buggy_add(2, 3)) [EOF] (Pdb) 2 (Pdb) 3 (Pdb) 5 (Pdb) --Return-- > buggy_add.py(4)buggy_add()->5 -> return total (Pdb) 5
In practice — this is the everyday "why is this test failing" tool. Before a bug
ever reaches production logging, a developer chasing down a failing test or a script
that's misbehaving locally reaches for exactly this — dropping a breakpoint() at the
suspect line and inspecting live variables — far more often than reading logs, since
the code hasn't shipped anywhere yet.
8.6 Assertions, Tracing and Diagnostics
The assert statement's mechanics (syntax, AssertionError, the -O stripping
behavior) are covered in 7.9 — this section is about using it as a debugging tool.
Fail fast, at the source. Without an assertion, a corrupted value can travel through several more function calls before it finally causes a crash — and by then, the traceback points at the symptom, not the cause. An assertion placed right where an invariant is expected to hold turns that into an immediate, precisely located failure:
def divide_all(nums, divisor):
assert divisor != 0, "divisor must not be zero" # catches the real cause immediately
return [n / divisor for n in nums]
print(divide_all([10, 20, 30], 5)) # [2.0, 4.0, 6.0]
try:
divide_all([10, 20], 0)
except AssertionError as e:
print("AssertionError:", e) # AssertionError: divisor must not be zero
[2.0, 4.0, 6.0] AssertionError: divisor must not be zero
Assertions and pdb (8.5) pair naturally: an assertion tells you that and where
something went wrong; when the message alone isn't enough to explain why, that's the
moment to drop a breakpoint() right before the failing assert and inspect the live
state that led to it.
Common mistake: using assert for input validation or security/permission checks.
assert statements are meant for catching programmer bugs during development, and
Python lets them be stripped out entirely: running with python -O (or setting
PYTHONOPTIMIZE) removes every assert from the compiled bytecode, as if it were never
written. A permission check written as assert user_is_admin, "not an admin" simply
vanishes in an optimized run — silently granting access. Use a real if ...: raise
PermissionError(...) (or equivalent) for anything that must hold in production.
import subprocess, tempfile, os
script = (
"def check_permission(user_is_admin):\n"
" assert user_is_admin, 'not an admin' # a security check written as an assert\n"
" return 'granted'\n"
"\n"
"print(check_permission(False))\n"
)
with tempfile.NamedTemporaryFile("w", suffix=".py", delete=False) as f:
f.write(script)
script_path = f.name
normal = subprocess.run(["python3", script_path], capture_output=True, text=True)
optimized = subprocess.run(["python3", "-O", script_path], capture_output=True, text=True)
print("normal run: ", normal.stderr.strip().splitlines()[-1])
print("python -O run:", optimized.stdout.strip())
os.remove(script_path)
# normal run: AssertionError: not an admin
# python -O run: granted -> the whole permission check silently vanished
normal run: AssertionError: not an admin python -O run: granted