Python Logging and Debugging: Tracebacks, logging and pdb

By Engr. Henry Akpan

Finding Out What Your Program Is Really Doing

Every programmer writes bugs. What separates beginners from professionals is how quickly they find them. Scattering print() calls works for a five-line script, but in a real application you need messages that can be switched on and off, sorted by importance, timestamped and saved to files. And when something crashes, you need to read the error and inspect the program's state. This tutorial covers Python logging and debugging: reading tracebacks, debugging strategies, the logging module (levels, formats, named loggers, handlers and logging exceptions), assertions, and the built-in debugger pdb with breakpoint(). It builds on the tutorial on exception handling.

Reading a Traceback

When an exception is not caught, Python prints a traceback: the chain of function calls that led to the error, with the most recent call last.

import traceback

def average(marks):
    return sum(marks) / len(marks)

def report(students):
    for name, marks in students.items():
        print(name, average(marks))

try:
    report({"Ada": [70, 80], "Bayo": []})
except ZeroDivisionError:
    lines = traceback.format_exc().strip().splitlines()
    print(lines[0])
    print(lines[-1])

Output:

Ada 75.0
Traceback (most recent call last):
ZeroDivisionError: division by zero

A full traceback lists each call with its file, line number and code: here, the call to report, then the call to average, then the division. Read it from the bottom up:

  1. The last line gives the exception type and message: ZeroDivisionError: division by zero.
  2. The line above it shows where the error happened: return sum(marks) / len(marks), in average.
  3. Moving up shows how the program got there: report called average with Bayo's empty list.

The bug is not really the division. It is the missing check for a student with no marks.

A Debugging Strategy

  1. Reproduce the bug reliably, with the smallest input that triggers it.
  2. Read the error carefully, especially the last line of the traceback.
  3. Form a hypothesis about the cause, and test it by inspecting values, using logging or the debugger.
  4. Narrow it down: check the values halfway through the process, then halve the suspect region again, like a binary search.
  5. Fix the cause, not the symptom, and add a test so that the bug cannot quietly return.

Explaining the code line by line to someone else, or even to a rubber duck on your desk ("rubber-duck debugging"), often reveals the mistake.

Why Logging Instead of print?

  • Log messages have levels, so you can show detailed debugging output while developing and only warnings and errors in production, without editing the code.
  • They can include the time, the module and the line number automatically.
  • They can go to the screen, to a file, or to both, and libraries can log without cluttering your program's normal output.

Log Levels

From least to most serious:

  • DEBUG: detailed information for diagnosing problems.
  • INFO: confirmation that things are working as expected.
  • WARNING: something unexpected happened, or may soon cause a problem, but the program continues. This is the default level.
  • ERROR: a serious problem stopped some function from working.
  • CRITICAL: a very serious error. The program itself may be unable to continue.

Setting a level shows messages at that level and above.

import logging
import sys

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

logging.debug("not shown: below the INFO level")
logging.info("starting the results report")
logging.warning("student %s has no marks", "Bayo")
logging.error("could not open %s", "results.csv")

Output:

INFO: starting the results report
WARNING: student Bayo has no marks
ERROR: could not open results.csv
  • basicConfig sets up logging once, near the start of the program. stream=sys.stdout sends messages to standard output. By default they go to standard error. force=True replaces any earlier configuration. It is used here because each example reconfigures logging.
  • Pass values as arguments ("has no marks", "Bayo" with %s) instead of building an f-string. The message is then formatted only if it will actually be shown.

Formatting Log Messages

The format string chooses what each line contains. Common fields include %(asctime)s (date and time), %(levelname)s, %(name)s (the logger's name), %(funcName)s, %(lineno)d and %(message)s. A typical production format is "%(asctime)s %(levelname)s %(name)s: %(message)s". The time changes on every run, so it is left out of the examples here.

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

def compute_gpa(points, units):
    logging.debug("points=%s units=%s", points, units)
    gpa = sum(p * u for p, u in zip(points, units)) / sum(units)
    logging.info("GPA computed: %.2f", gpa)
    return gpa

compute_gpa([5, 4, 3], [3, 2, 1])

Output:

[DEBUG] compute_gpa: points=[5, 4, 3] units=[3, 2, 1]
[INFO] compute_gpa: GPA computed: 4.33

Named Loggers

In larger programs, each module creates its own logger, conventionally with logging.getLogger(__name__), so that every message shows where it came from, and the level of each part of the program can be set separately.

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

db_log = logging.getLogger("app.database")
pay_log = logging.getLogger("app.payments")

db_log.info("connected")
pay_log.warning("payment of ₦%s pending", "5,000")

logging.getLogger("app.database").setLevel(logging.WARNING)   # quieten one part
db_log.info("this info message is now hidden")
db_log.error("query failed")

Output:

app.database INFO: connected
app.payments WARNING: payment of ₦5,000 pending
app.database ERROR: query failed

Loggers form a hierarchy by name, so settings on "app" also apply to "app.database" and "app.payments". Third-party libraries use the same system. For example, logging.getLogger("urllib3").setLevel(logging.WARNING) silences a chatty library.

Logging to a File

A handler decides where messages go. Several handlers can be attached to the same logger, each with its own level and format.

logger = logging.getLogger("results")
logger.setLevel(logging.DEBUG)
logger.propagate = False                      # do not also pass messages to the root logger

file_handler = logging.FileHandler("app.log", mode="w", encoding="utf-8")
file_handler.setLevel(logging.DEBUG)          # everything goes to the file
file_handler.setFormatter(logging.Formatter("%(levelname)s %(message)s"))

console = logging.StreamHandler(sys.stdout)
console.setLevel(logging.WARNING)             # only problems go to the screen
console.setFormatter(logging.Formatter("! %(message)s"))

logger.addHandler(file_handler)
logger.addHandler(console)

logger.debug("loaded 120 records")
logger.info("report generated")
logger.warning("3 records had missing marks")
file_handler.close()

print(open("app.log", encoding="utf-8").read().strip())

Output:

! 3 records had missing marks
DEBUG loaded 120 records
INFO report generated
WARNING 3 records had missing marks

The console shows only the warning, while the file keeps the full record for later investigation. For long-running servers, logging.handlers.RotatingFileHandler starts a new file when the current one gets too large.

Logging Exceptions

Inside an except block, logger.exception() logs an ERROR message together with the full traceback, so that the cause is recorded even though the program carries on.

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

def safe_average(name, marks):
    try:
        return sum(marks) / len(marks)
    except ZeroDivisionError:
        logging.exception("cannot average marks for %s", name)
        return None

result = safe_average("Bayo", [])
print("result:", result)

When run, this prints ERROR: cannot average marks for Bayo, followed by the traceback ending in ZeroDivisionError: division by zero, and then result: None. Never silently swallow an exception with a bare except: pass. At the very least, log it.

Assertions

An assert statement checks something that must be true if the program is correct. If it is false, Python raises an AssertionError immediately, close to the real cause, instead of letting bad data spread.

def apply_discount(price, percent):
    assert 0 <= percent <= 100, f"invalid discount {percent}%"
    return price * (100 - percent) / 100

print(apply_discount(2000, 25))
try:
    apply_discount(2000, 150)
except AssertionError as e:
    print("AssertionError:", e)

Output:

1500.0
AssertionError: invalid discount 150%

Use assertions for checking your own assumptions, not for validating user input. Assertions can be disabled with the -O option, so input checks should raise proper exceptions such as ValueError.

The Python Debugger: pdb and breakpoint()

A debugger pauses a running program so that you can inspect variables, step through code one line at a time, and see exactly where things go wrong. Insert breakpoint() where you want the program to pause:

In a terminal:

def average(marks):
    breakpoint()                  # execution pauses here
    return sum(marks) / len(marks)

# Running the program shows a (Pdb) prompt. Useful commands:
#   p marks       print the value of a variable (here: [])
#   n             run the next line
#   s             step into a function call
#   c             continue until the next breakpoint
#   l             list the source code around the current line
#   w             show where you are in the call stack
#   q             quit the debugger

You can also run any script under the debugger with python -m pdb script.py, or, after a crash in the interactive shell, inspect the failed state with import pdb; pdb.pm() ("post-mortem"). Editors such as VS Code and PyCharm provide the same features graphically: click in the margin to set a breakpoint, then press F5 to debug.

Common Mistakes with Python Logging and Debugging

  • Calling basicConfig more than once, or after logging has started. Later calls are ignored unless you pass force=True.
  • Using f-strings in log calls, such as logging.debug(f"...{big}..."), which builds the string even when the message is not shown.
  • Leaving debugging print calls in finished code, instead of DEBUG-level log messages that can be switched off.
  • Silencing errors with except: pass, which hides the information you need.
  • Reading a traceback from the top instead of starting with the last line.

Python Logging and Debugging: Practice Exercises

  1. Configure logging so that only WARNING and more serious messages are shown, using the format "LEVEL - message".
  2. Write a function parse_score(text) that converts text to an integer, logging a warning and returning 0 when the text is not a number.
  3. Add an assertion to parse_score that the result is between 0 and 100.

Sample solutions:

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

def parse_score(text):
    try:
        score = int(text)
    except ValueError:
        logging.warning("not a number: %r", text)
        return 0
    assert 0 <= score <= 100, f"score out of range: {score}"
    return score

logging.info("this is hidden")
print([parse_score(t) for t in ["85", "abc", "40"]])
try:
    parse_score("120")
except AssertionError as e:
    print(e)

Output:

WARNING - not a number: 'abc'
[85, 0, 40]
score out of range: 120

Conclusion

Effective Python logging and debugging starts with reading tracebacks from the bottom up, then follows a strategy: reproduce, hypothesise, inspect, narrow down and fix the cause. The logging module replaces scattered print calls with messages at five levels (DEBUG, INFO, WARNING, ERROR, CRITICAL), configurable formats, named loggers for each module, and handlers that send messages to the screen and to files. Use logger.exception to record errors with their tracebacks, assert to check your own assumptions, and breakpoint() with pdb to pause and inspect a running program.

Related Tutorials