F7.2 · LESSON 2 OF 6

Debugging and logs

Build a small HTTP service with clear boundaries, tests, logs and a repeatable runtime.

THE IDEA

Debugging is narrowing, not guessing

A wrong answer at the end of a program means some earlier step produced a wrong value. The method is always the same: reproduce the failure with an input that fails every time, narrow down the first place where reality differs from what you expected, then change one cause and re-run. If you change three things at once you do not know which one fixed it.

Prints at checkpoints. The first line that disagrees with your hand calculation is where to look.

s = subtotal(lines);        print("subtotal", s)      # expected 370
d = apply_discount(s, code); print("discount", d)      # expected 333
t = add_tax(d);             print("total", t)         # expected 359

Halve the search

With eight steps you do not need to inspect all eight. Check the middle: if the value is already wrong there, the bug is in the first half; if it is right, in the second. Each look halves the suspects, so eight steps need at most three looks. Try it, then switch bug scenarios and see that the same strategy works wherever the bug hides.

The program starts at 1000 and runs eight steps. One step has a bug. You know what each value should be. Click a checkpoint to print the real value there.

startvalue 1000

1. add shipping 250

2. discount x 90 / 100

3. add handling fee 40

4. subtract coupon 15

5. tax x 108 / 100

6. cap at 2000

7. add donation 5

8. format for display

Suspect range: steps 1 to 8. Inspections used: 0. Halving each time needs at most 3.

Find the culprit step with as few printed checkpoints as possible. Note that a later step can hide or change a wrong value, which is why you look for the FIRST wrong value.

Predict first. You print the value after step 4 and it is correct. Where is the bug?

Logs: prints that survive

A print is for you, now. A log is for whoever runs the program later, often when you are not there. Logging adds a level (DEBUG, INFO, WARNING, ERROR), a timestamp and a message you can filter. A server handles many requests at once, so their lines interleave. A request id repeated on every line is what lets you pull one request's story out of the mix.

Filter by request id log the whole order object

12:00:01.012INFOreq-9f3acheckout started: 2 lines, code=SAVE10, card ending 4242

12:00:01.015INFOreq-77b1checkout started: 1 lines, code=VIP25, card ending 1111

12:00:01.020INFOreq-9f3asubtotal=370

12:00:01.021WARNINGreq-77b1unknown discount code 'VIP52', no discount applied

12:00:01.024INFOreq-9f3aafter discount=333

12:00:01.026INFOreq-77b1subtotal=1000

12:00:01.031INFOreq-9f3atotal=359

12:00:01.033ERRORreq-77b1payment gateway timeout after 2000 ms

Without the request id column you could not tell which WARNING belongs to which customer. With it, one filter gives one story.

Filter by request id to follow one request. Then tick the box to see what a careless log line leaks.

Log identifiers, counts and outcomes: request id, number of lines, final total, which stage failed.

Don't

Log whole payloads, passwords, tokens or full card numbers. Logs are copied, shipped and read by many people.

Chapter context

Engineering makes a program understandable when it fails or changes. Separate pure calculations from external I/O so behavior can be checked cheaply and errors can be connected to specific inputs.

TRY IT YOURSELF

Exercise: find two bugs and make the logs useful

checkout(request_id, raw_lines, code, card) should return the final price in minor units: subtotal, then discount, then 8 percent tax, each rounded down. For ["2 x 125", "3 x 40"] and code SAVE10 the correct answer is **359** (370, then 333, then 359).
Run it. It prints something else. Add print or log calls between the stages to see the first stage whose value is wrong, then fix that stage. There are **two separate bugs**.
Then make the logging safe and useful: every log message must contain the request id, the card number must never appear in a log, a normal call should log at least one record per stage, and an unknown discount code should log a warning.
The checker calls checkout with other orders and captures what you log, so the fix has to be real.

import logging, sys
logging.basicConfig(level=logging.DEBUG, format="%(levelname)s %(message)s", stream=sys.stdout, force=True)
log = logging.getLogger("shop")

DISCOUNTS = {"SAVE10": 10, "VIP25": 25}   # percent off
TAX_PERCENT = 8

def parse_line(text):
    qty, price = text.split(" x ")
    return int(qty), int(price)

def subtotal(lines):
    total = 0
    for i in range(1, len(lines)):
        qty, price = lines[i]
        total += qty * price
    return total

def apply_discount(amount, code):
    pct = DISCOUNTS.get(code, 0)
    return amount - amount * pct // 100

def add_tax(amount):
    return amount + amount * TAX_PERCENT // 100

def checkout(request_id, raw_lines, code, card):
    log.info("checkout started for order %s", {"lines": raw_lines, "code": code, "card": card})
    lines = [parse_line(t) for t in raw_lines]
    s = subtotal(lines)
    d = apply_discount(s, code)
    return add_tax(d)

print(checkout("req-1001", ["2 x 125", "3 x 40"], "save10", "4242424242424242"))   # should be 359

Ctrl/⌘ + Enter runs it

Stuck, or something not working? You can come back to it any time.

CHECK YOUR UNDERSTANDING

Why keep a request identifier in logs?

AIt connects events from the same operation.BIt makes the log file smaller by removing repeated words.CIt proves the request was authenticated before it was handled.

Chapter reference: math, worked example & code

This section belongs to the whole chapter, so it is the same on every lesson in it and may cover a different lesson's topic. The code for the experiment you just ran is inside the experiment itself.

Math and notation

For money examples, use integer minor units rather than binary floating point. The subtotal is sum(quantity × unit_price), and the domain must specify rounding and tax rules before those operations are implemented.

Worked example

Two items cost 125 minor units each and three cost 40 each. The subtotal is 2×125 + 3×40 = 370. A test can exercise this calculation without starting an HTTP server. Request parsing and response formatting need separate checks.

Reference code

The following example uses the Python standard library and does not call a remote service.

def subtotal(items):
    return sum(quantity * price for quantity, price in items)
assert subtotal([(2, 125), (3, 40)]) == 370
assert subtotal([]) == 0

Python examples are provided for study and local execution; this page does not execute Python.

Common mistakes

Test coverage counts executed lines, not verified requirements. A container does not turn an unsafe operation into a safe one. JSON validity alone does not establish application validity.