Debugging with print, Logging and a Debugger

Series: Testing & Debugging lecture 2/6 (beginner). For new developers who debug by adding print everywhere and hoping. After this lecture you can choose between print, logging and a debugger, drive pdb and lldb through a real bug, and shrink a confusing bug to a two-line reproduction.

Lecture 1 was about reading the report a program leaves when it crashes. Most bugs do not crash. The total is wrong, a report picks the wrong row, a loop never ends. That is the problem this lecture solves for the junior developer on their first on-call rotation: the program runs, the answer is wrong, and nobody has a stack trace to give you.

Everything below was run on an Apple Silicon Mac (M1 Pro) with Python 3.9.6, PHP 8.5.6, Apple clang 21 and lldb-2103. Paths were shortened to ~/demo/.

The bug we will chase

A shop applies a 10 % coupon. Here is the code a junior developer was handed during onboarding:

import sys


def apply_discount(price, percent):
    return price - price * percent // 100


def cart_total(items, percent):
    total = 0
    for name, price, qty in items:
        total += apply_discount(price, percent) * qty
    return total


CART = [("pen", 120, 3), ("notebook", 300, 2)]
COUPON = {"WELCOME10": 0.1, "BROKEN": None}   # bug: 0.1 should be 10

if __name__ == "__main__":
    print(cart_total(CART, COUPON[sys.argv[1]]))

$ python3 discount.py WELCOME10
960.0

The expected total is 108 × 3 + 270 × 2 = 864. We got 960, which is the price with no discount, and it is a float. No exception, no traceback. The comment gives the bug away, of course; the point is to see what each tool would have told you without it.

print debugging, and the C trap that eats your prints

The first instinct is print(price, percent) inside apply_discount. It works, and for a ten-line script it is the right tool. Two problems appear as soon as code gets bigger:

1. Prints have no level, so you cannot turn them off without editing code, and forgotten ones end up in production output.
2. Output can be buffered: held in memory and written later. If the program crashes first, it is gone.

The second one is not theoretical. This C program looks up three user ids; id 7 does not exist, so find_user returns NULL:

#include <stdio.h>
#include <string.h>

struct user { int id; const char *name; };

static struct user USERS[] = { {1, "alex"}, {2, "sam"}, {3, "jordan"} };

static struct user *find_user(int id) {
    for (size_t i = 0; i < sizeof USERS / sizeof USERS[0]; i++)
        if (USERS[i].id == id) return &USERS[i];
    return NULL;                       /* not found */
}

static size_t name_length(int id) {
    struct user *u = find_user(id);
    return strlen(u->name);            /* crashes when u == NULL */
}

int main(void) {
    int ids[] = {2, 3, 7};
    for (int i = 0; i < 3; i++)
        printf("id=%d len=%zu\n", ids[i], name_length(ids[i]));
    return 0;
}

$ clang -std=c17 -Wall -Wextra -g -O0 users.c -o users
$ ./users > out.txt; echo "exit=$?"; wc -c < out.txt
exit=139
       0

Two lines were printed before the crash, but the file is empty. When stdout goes to a file or a pipe, C buffers it in blocks; the crash (exit 139, a segmentation fault) killed the process before the block was written. In a terminal you would have seen the lines, because a terminal gets line buffering. Changing the printf to fprintf(stderr, …), which is unbuffered, gave us both lines (id=2 len=3, id=3 len=6) before the same exit 139. This is why "the log stops before the crash" so often misleads people during incidents.

lldb: where did the C program crash, and with what?

No prints needed. Build with -g (debug info) and let the debugger catch the crash. We fed lldb a command file (run, bt, frame variable, up, frame variable, quit) with lldb -s lldb.txt ./users (launch messages and part of the source listing trimmed):

(lldb) run
id=2 len=3
id=3 len=6
Process 36458 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x8)
    frame #0: 0x0000000100000634 users`name_length(id=7) at users.c:16:22
   14   static size_t name_length(int id) {
   15       struct user *u = find_user(id);
-> 16       return strlen(u->name);            /* crashes when u == NULL */
(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x8)
  * frame #0: 0x0000000100000634 users`name_length(id=7) at users.c:16:22
    frame #1: 0x00000001000005b4 users`main at users.c:22:43
    frame #2: 0x0000000188a244e4 dyld`start + 6992
(lldb) frame variable
(int) id = 7
(user *) u = NULL
(lldb) up
frame #1: 0x00000001000005b4 users`main at users.c:22:43
-> 22           printf("id=%d len=%zu\n", ids[i], name_length(ids[i]));
(lldb) frame variable
(int[3]) ids = ([0] = 2, [1] = 3, [2] = 7)
(int) i = 2

• bt (backtrace) is the stack trace from lecture 1.
• frame variable prints every local variable of the selected frame: u = NULL.
• up moves to the caller, so you can see which input caused it: i = 2, id 7.
• address=0x8 is a nice detail: name sits 8 bytes into struct user (4-byte int, 4 bytes of padding), so reading u->name with u == NULL touches address 8.

The lines id=2 len=3 appear here because lldb runs the program on a terminal. For more lldb (watchpoints, -O2 builds), see C performance, Make and lldb.

pdb: stepping through the Python bug

pdb is Python's built-in debugger. Start it with python3 -m pdb discount.py WELCOME10. The core commands:

We drove the session from a here-doc so it is reproducible. Plain pdb does not echo commands it reads from a file, so we used a 20-line wrapper whose only change is printing each command after the (Pdb) prompt. Typing them by hand gives the same output.

> ~/demo/discount.py(1)<module>()
-> import sys
(Pdb) break 11
Breakpoint 1 at ~/demo/discount.py:11
(Pdb) continue
> ~/demo/discount.py(11)cart_total()
-> total += apply_discount(price, percent) * qty
(Pdb) p name, price, qty, percent
('pen', 120, 3, 0.1)
(Pdb) step
--Call--
> ~/demo/discount.py(4)apply_discount()
-> def apply_discount(price, percent):
(Pdb) where
  … 2 debugger frames trimmed
  ~/demo/discount.py(19)<module>()
-> print(cart_total(CART, COUPON[sys.argv[1]]))
  ~/demo/discount.py(11)cart_total()
-> total += apply_discount(price, percent) * qty
> ~/demo/discount.py(4)apply_discount()
-> def apply_discount(price, percent):
(Pdb) p price * percent
12.0
(Pdb) p price * percent // 100
0.0
(Pdb) return
--Return--
> ~/demo/discount.py(5)apply_discount()->120.0
-> return price - price * percent // 100
(Pdb) next
> ~/demo/discount.py(10)cart_total()
-> for name, price, qty in items:
(Pdb) p total
360.0
(Pdb) quit

The third p is the moment of discovery: percent is 0.1, so price * percent // 100 is 12.0 // 100, which is 0.0. The discount is always zero, and the float leaks into total. You did not have to guess where to put a print; you stopped at the loop and looked.

Post-mortem: debugging after the crash

The BROKEN coupon maps to None and crashes. python3 -m pdb -c continue discount.py BROKEN runs until the exception and then drops you into the frame that raised it:

TypeError: unsupported operand type(s) for *: 'int' and 'NoneType'
Uncaught exception. Entering post mortem debugging
> ~/demo/discount.py(5)apply_discount()
-> return price - price * percent // 100
(Pdb) p price, percent
(120, None)
(Pdb) up
> ~/demo/discount.py(11)cart_total()
-> total += apply_discount(price, percent) * qty
(Pdb) p name, qty
('pen', 3)
(Pdb) quit

From inside a program, import pdb; pdb.post_mortem() in an except block, or breakpoint() (Python 3.7+) anywhere, gives you the same prompt.

logging: levels, format and UTC timestamps

A debugger needs you at the keyboard while the bug happens. In production, at night, you are not. That is what logging is for: prints with a level (DEBUG < INFO < WARNING < ERROR < CRITICAL), a timestamp and a name, that you can turn up or down without touching code.

import logging
import sys
import time

logging.Formatter.converter = time.gmtime          # timestamps in UTC
logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)sZ %(levelname)-7s %(name)s: %(message)s",
    datefmt="%Y-%m-%dT%H:%M:%S",
    stream=sys.stderr,
)
log = logging.getLogger("checkout")


def apply_discount(price, percent):
    log.debug("apply_discount price=%r percent=%r", price, percent)
    if not 0 <= percent <= 100:
        log.warning("percent out of range: %r", percent)
    return price - price * percent // 100


def checkout(order_id, items, percent):
    total = sum(apply_discount(p, percent) * q for p, q in items)
    log.info("order=%s items=%d total=%s", order_id, len(items), total)
    return total


checkout("A-1001", [(120, 3), (300, 2)], 10)
checkout("A-1002", [(120, 1)], 0.1)
try:
    checkout("A-1003", [(120, 1)], None)
except TypeError:
    log.exception("checkout failed order=%s", "A-1003")

2026-11-14T06:00:21Z INFO    checkout: order=A-1001 items=2 total=864
2026-11-14T06:00:21Z INFO    checkout: order=A-1002 items=1 total=120.0
2026-11-14T06:00:21Z ERROR   checkout: checkout failed order=A-1003
Traceback (most recent call last):
  File "~/demo/log_demo.py", line 31, in <module>
    checkout("A-1003", [(120, 1)], None)
  File "~/demo/log_demo.py", line 23, in checkout
    total = sum(apply_discount(p, percent) * q for p, q in items)
  File "~/demo/log_demo.py", line 23, in <genexpr>
    total = sum(apply_discount(p, percent) * q for p, q in items)
  File "~/demo/log_demo.py", line 17, in apply_discount
    if not 0 <= percent <= 100:
TypeError: '<=' not supported between instances of 'int' and 'NoneType'

What makes these lines useful at 3 a.m.:

• UTC with a Z. Servers, phones and teammates live in different time zones; a log line without a zone cannot be lined up with anything else. logging uses local time unless you set converter = time.gmtime.
• key=value pairs (order=A-1002) that you can grep.
• log.exception inside except adds the full traceback (lecture 1's "print only the message" mistake, fixed).
• The second line gives the bug away to anyone reading carefully: total=120.0, a float, and no discount. The range check did not fire, because 0.1 is between 0 and 100. Logs show symptoms; you still have to think.

Set level=logging.DEBUG and the apply_discount price=120 percent=10 lines appear, without editing a single call. PHP has the same idea in error_log(): on the CLI it writes to stderr, and with php -d error_log=app.log it wrote [14-Nov-2026 06:05:50 UTC] checkout order=A-1002 percent=0.1 type=float to a file. Check that the date.timezone setting says UTC on your server, as it did on ours. Shell scripts have their own version of this in robust shell scripts with cron and logging.

When the program hangs: faulthandler

A hang prints nothing. Python's faulthandler can dump every thread's stack after a timeout:

import faulthandler
import time

faulthandler.dump_traceback_later(2, exit=True)   # print every thread's stack after 2 s


def wait_for_payment(status):
    while status != "paid":        # bug: status is never refreshed
        time.sleep(0.1)


wait_for_payment("pending")

Timeout (0:00:02)!
Thread 0x00000001f582e180 (most recent call first):
  File "~/demo/hang.py", line 9 in wait_for_payment
  File "~/demo/hang.py", line 12 in <module>

python3 -X faulthandler does the same for segmentation faults in C extensions (Fatal Python error: Segmentation fault, exit 139).

Rubber duck and minimal repro: two bugs found without tools

Rubber-duck debugging means explaining your code, line by line, out loud, to someone who knows nothing, a rubber duck if no colleague is free. This function tags blog posts:

def add_tag(post, tag, tags=[]):
    tags.append(tag)
    post["tags"] = tags
    return post


a = add_tag({"title": "First post"}, "python")
b = add_tag({"title": "Second post"}, "php")
print(a)
print(b)

{'title': 'First post', 'tags': ['python', 'php']}
{'title': 'Second post', 'tags': ['python', 'php']}

Explaining it: "tags defaults to a new empty list on each call… does it?" Saying "on each call" out loud is where it breaks. Python evaluates the default once, when def runs, so every call shares one list. The fix is tags=None and tags = [] if tags is None else tags.

A minimal repro is the smallest program that still shows the bug. A 32-line release report read this CSV and printed the latest build per platform:

app,platform,build,date,notes
shop,ios,8,2026-09-30,first public build
shop,ios,9,2026-10-14,fix login crash
shop,android,9,2026-10-14,fix login crash
shop,ios,10,2026-11-02,new checkout
shop,android,10,2026-11-02,new checkout
shop,android,11,2026-11-10,hotfix coupon rounding

$ python3 release_report.py releases.csv
release report (2026-11-14)
  android  build   9  2026-10-14  fix login crash
  ios      build   9  2026-10-14  fix login crash

Android 11 and iOS 10 are newer. We cut the program step by step, checking that the bug survived each cut: inline the data, drop the grouping, drop the dates and notes, drop the CSV module. It ended as one line:

$ python3 -c 'print(max(["9", "10"]))'
9
$ python3 -c 'print(max(["9", "10"], key=int))'
10

CSV gives you strings, and strings compare character by character: "9" > "1". The fix in the report is key=lambda r: int(r["build"]). A one-line repro is also the best thing to paste into a question or bug report; nobody can help with a 32-line script and a private CSV.

Measured: what logging costs when it is off

Is it safe to leave log.debug calls in hot code? We timed 200,000 calls of each style, 7 repetitions, median, Python 3.9.6, Apple M1 Pro. The logger level was INFO, so every debug call was disabled; the enabled info call wrote to an in-memory buffer with a timestamp.

def debug_lazy(i):    log.debug("order=%s i=%d", ORDER, i)
def debug_fstring(i): log.debug(f"order={ORDER} i={i}")
def debug_guarded(i):
    if log.isEnabledFor(logging.DEBUG):
        log.debug("order=%s i=%d", ORDER, i)
def info_enabled(i):  log.info("order=%s i=%d", ORDER, i)

A disabled debug call costs about 0.3 µs, so a thousand of them per request is 0.3 ms: fine. An f-string costs almost three times as much even when nothing is logged, because Python builds the string before debug can say "not interested". An enabled line costs about 10 µs, 35 times a disabled one. Log what you need at INFO, put details at DEBUG with %-style arguments, and guard truly expensive arguments with isEnabledFor. For profiling the rest of your program, see Python profiling and optimization.

Honest limits and version notes

• Python 3.9.6 here. breakpoint() exists since 3.7. Newer Python versions keep adding pdb features; we only ran what 3.9 has. Absolute timings differ between versions and machines; the ratios are what to remember.
• python3 -m trace --trace prints every executed line. It ran fine here and is handy for "which branch did it take?", but on real programs it produces thousands of lines.
• PHP: Xdebug is not installed on this Mac, so we did not show a step debugger for PHP; error_log() and php -d settings were run.
• lldb is the debugger on macOS. gdb is not installed here; its commands differ (bt is the same, frame variable is info locals).
• When a debugger and logs disagree, trust the code you can read. An AI assistant once gave us a confident wrong diagnosis that the logs disproved; that story is in an AI agent's wrong diagnosis caught by logs.

Exercises

1. In the pdb session above, which single command would have shown you percent at the moment apply_discount returned 120.0?
2. A C program run as ./app >> app.log crashes, and the log ends 50 lines before the crash. Give two ways to make the last lines appear.
3. Rewrite log.debug(f"payload={json.dumps(big)}") so it costs almost nothing when DEBUG is off.

Answers

1. p percent (or p price, percent) while stopped at the --Return-- line; the frame is still alive there. args (a) also prints all arguments of the current function.
2. Write debug output to stderr (unbuffered), or call setvbuf(stdout, NULL, _IOLBF, 0) at the start of main for line buffering, or fflush(stdout) after each important line. Better still, run it under lldb or with -fsanitize=address to see the crash itself.
3. if log.isEnabledFor(logging.DEBUG): log.debug("payload=%s", json.dumps(big)). Passing "%s", big alone avoids building the message but not json.dumps; the guard avoids both.

Previous: Lecture 1: reading error messages and stack traces · Next: Lecture 3: your first unit tests · Also in this series: test doubles, flaky tests, git bisect. Back to the programming learning roadmap.