Production Python for Data Engineers

Module 6: Logging, Observability, Debuggability

What you'll learn in this module

By the end of this module, you'll be able to:

  • Explain what makes a log line actually useful for debugging, versus just noise
  • Add structured logging with a run ID, so a real failure can be diagnosed from the logs alone — no rereading code, no rerunning
  • Recognize why a stray print() in an otherwise-structured codebase is a common, dangerous regression point
  • Know exactly what belongs in a log line, and what never does — even when it feels convenient to just log everything

Let's begin.

Let's start with a question

Have you ever had a job fail at 3am, and the only thing you had to go on was a one-line error message with no context at all?

No record ID. No indication of which of the ten thousand items being processed actually failed. Just "something went wrong," and a long morning of adding print statements and rerunning the job, hoping to catch it happening again.

That's not a logging problem in the sense of "not enough logs." It's a logging problem in the sense of "logs that don't actually answer the question you'll have later." This module is about closing that gap — writing logs for the version of you who has to debug this at 3am, with nothing but the log line in front of them.

Why this matters in data engineering

Ask yourself: when your pipeline processes a batch of a thousand records and one of them fails, how do you find out which one, and why?

If the honest answer involves rerunning the job with extra print statements added, or manually counting lines in a log file to guess which record corresponds to which output — that's a real cost, paid every single time something breaks. In production, at real scale, "just rerun it and add some prints" often isn't even an option — the failure might not reproduce, or the job might be too expensive to rerun casually.

Good logging turns "I need to reproduce this to understand it" into "I can read exactly what happened from what's already been recorded." That difference is the entire subject of this module.

The core idea: logs written for the reader, not the writer

Structured logging vs. print statements

A print() statement writes whatever string you hand it. A structured logging library — structlog, in this module — writes distinct, named fields: not "sending email for order 1003," but event: "email_send_started", order_id: "1003". The difference matters because structured fields can be searched, filtered, and correlated by a real log aggregation tool. A plain string can only be read, one line at a time, by a human who already knows roughly what they're looking for.

The run ID: tying a whole story together

A single log line rarely tells the whole story. A run ID — one identifier, generated once per pipeline run, attached to every log line that run produces — lets you pull every event from one specific run out of a sea of unrelated log lines, and see the whole sequence of what happened, in order.

Choosing fields deliberately, every time

Here's a question worth asking about every single log line you write: if someone searched every log in the company for this exact piece of information, would I be comfortable with that? A record ID — usually fine. A customer's phone number, full address, or raw payment details — almost never fine, and yet astonishingly easy to log by accident, especially by logging an entire raw object "just to be safe."

Good structured logging isn't just about using the right library. It's about deciding, deliberately, which fields belong in a log line and which never do — the same discipline, applied every time, not just when someone remembers to think about it.

Manual lab: logs you can actually diagnose from

Getting the lab files

Download module-6-materials.zip:

bash
cd ~/courses/pp4de
cp /mnt/c/Users/yourname/Downloads/module-6-materials.zip course-materials/
cd course-materials
unzip module-6-materials.zip

Commit it:

bash
cd ~/courses/pp4de
git add course-materials/module-6
git commit -m "Add Module 6 lab materials"
git push

The scenario

You've inherited a small tool that sends order confirmation emails after checkout. Most of the time it works fine. Every so often, one email in a batch fails to send, and whoever's on call has to figure out which order it was — currently, by rerunning the job and watching closely, since the logs don't actually say.

Reproduce the problem first

  1. Go into the starter folder: 
    bash
    cd course-materials/module-6/starter
  2. Run it: 
    bash
    python3 run.py
  3. Read the output. Somewhere in the middle, you'll see: 
    Failed to send email: SMTP delivery failed: mailbox unavailable
  4. Now, without looking at the source code, answer this question: which order failed? ORD-1001? ORD-1003? There's no way to tell from this output — you'd have to count lines carefully, or add a print statement and run it again.
  5. Open notifier.py. Notice every log line is a plain string, with no consistent structure, and nothing ties any line back to a specific order or a specific run of the batch.

You've now experienced, directly, the exact problem this module exists to fix: a real failure, with a log line sitting right in front of you, that still can't actually tell you what you need to know.

Your task

Fix this so that:

  1. Every log line uses structured fields, not a plain string.
  2. A single run_id is generated once per batch, and appears on every log line from that run.
  3. Every order-related log line includes order_id, so a failure can be traced to the exact record that caused it.
  4. No customer PII — specifically, customer_email — ever appears in a log line. Nothing here needs it to diagnose a delivery failure.

A question worth asking before you look at the solution

Same habit as every module. If the solution looks different, ask why.

Here's the honest answer: the actual logic — loop through orders, try to send an email, catch a failure — doesn't change at all. What changes is entirely about how the pipeline talks about what it's doing, not what it actually does. That's worth sitting with: a huge amount of real debuggability work is exactly this kind of change — no new behavior, just making existing behavior legible after the fact.

Full worked solution

The complete solution lives in course-materials/module-6/solution/:

solution/
├── pyproject.toml
├── run.py                          # configures structlog for JSON output
└── src/
    └── notifier/
        ├── __init__.py
        ├── email_service.py        # unchanged - the simulated external service
        └── notifier.py             # structured logging, run_id, deliberate fields

notifier.py — the actual fix:

python
import uuid
from typing import TypedDict

import structlog

from notifier.email_service import send_confirmation_email

logger = structlog.get_logger()


class Order(TypedDict):
    order_id: str
    customer_email: str
    total: float


def process_orders(orders: list[Order]) -> None:
    run_id = str(uuid.uuid4())
    structlog.contextvars.clear_contextvars()
    structlog.contextvars.bind_contextvars(run_id=run_id)

    logger.info("batch_started", order_count=len(orders))

    for order in orders:
        order_id = order["order_id"]
        logger.info("email_send_started", order_id=order_id)
        try:
            send_confirmation_email(order_id, order["customer_email"], order["total"])
            logger.info("email_send_succeeded", order_id=order_id)
        except Exception as e:
            logger.error("email_send_failed", order_id=order_id, error=str(e))

    logger.info("batch_finished")

A few things worth noticing:

  • structlog.contextvars.bind_contextvars(run_id=run_id) — this is what makes run_id show up on every log line for the rest of this run, without you having to pass it into every single logger.info call by hand. Bind it once, at the top.
  • order_id=order_id appears on every order-related line. This is the deliberate choice this module is about — not logging the whole order object, just the one field that actually matters for diagnosis.
  • customer_email never appears anywhere in a log call. It's still passed into send_confirmation_email — the email service needs it to actually work — but it's never logged. That's a conscious omission, not an oversight.

run.py configures structlog to actually output structured JSON:

python
structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.JSONRenderer(),
    ],
)

Verify it, step by step

  1. Create a virtual environment and install: 
    bash
    cd course-materials/module-6/solution
python3 -m venv .venv
source .venv/bin/activate
pip install -e .
pip install mypy
  2. Run mypy --strict: 
    bash
    python -m mypy --strict src/notifier/ run.py
    Expected: Success: no issues found.
  3. Run it: 
    bash
    python run.py
  4. Find the line where "event": "email_send_failed" appears. Read just that one line — nothing else, no source code, no rerunning. Confirm you can answer, from that line alone: which order failed, and why? You should see something like: 
    json
    {"order_id": "ORD-1003", "error": "SMTP delivery failed: mailbox unavailable", "event": "email_send_failed", "run_id": "...", "timestamp": "..."}
  5. Scroll through the rest of the output and confirm customer_email never appears anywhere.

If step 4 let you answer "which order, and why" from one line, and step 5 confirmed no PII leaked into the logs, you've verified the actual thing this module set out to teach.

AI-assisted round

The task

Ask your assistant to add error handling for a new failure mode:

Output / Note

"Add handling for a new kind of failure — the email service can sometimes return a malformed response that we can't parse. When that happens, log enough detail to actually debug it later, since this failure mode is rare and hard to reproduce."

The known failure pattern to watch for

This is exactly the pattern behind this module's debugging drill, worth watching for directly: an AI assistant reaching for a bare print() — or an f-string dumping the entire raw object — specifically in an error-handling path, even in a project that's otherwise fully structured.

Here's what that tends to look like:

diff
      try:
          send_confirmation_email(order_id, order["customer_email"], order["total"])
          logger.info("email_send_succeeded", order_id=order_id)
+     except MalformedResponseError as e:
+         print(f"Malformed response for order: {order}, error: {e}")
+         raise
      except Exception as e:
          logger.error("email_send_failed", order_id=order_id, error=str(e))

Notice exactly where this happened — inside a try/except block, right next to two other lines that both use logger correctly. The print(f"...{order}...") doesn't just break the structured-logging convention; it dumps the entire raw order dictionary, including customer_email, straight into unstructured text — exactly the PII leak this module's concept section warned about, reintroduced in one line, in the one part of the file least likely to get a careful review.

The guardrail

If you catch this, write it down:

Output / Note

Module 6 guardrail: Check every new error-handling path an AI assistant adds, specifically for a bare print() or f-string, even in a project that's otherwise fully structured. Error paths are the most common place this regression sneaks in — and check exactly what gets logged, not just whether something does. A raw object dump in an error handler can leak PII even when every other log line in the file is clean.

If your assistant used logger.error(...) correctly, with deliberately chosen fields, without being told to — log that too.

Common mistakes

  • Logging the whole object "just in case it's useful later." It might be useful. It's also how PII ends up in a shared log aggregation tool that dozens of engineers can search. Choose fields deliberately, every time.
  • A print() anywhere in a codebase that's standardized on structured logging. Even one bypasses every downstream tool built to search, filter, and alert on structured fields — and it's often invisible until someone specifically needs the log it broke.
  • No run ID, or a run ID that isn't actually attached to every log line. A run ID that's only on the first log line of a run is barely better than no run ID at all — the whole point is being able to pull the complete story for one run out of a shared log stream.
  • Treating the error path as less important to structure than the happy path. In practice, it's the opposite — the error path is exactly where you need a diagnosable log line most, and exactly where it's most likely to be rushed.

Capstone tie-in

Step 1: Open your capstone repo and start the infrastructure

Confirm the title bar says pp4de [WSL: Ubuntu].

bash
docker compose start
docker compose ps

Step 2: Add structured logging to your capstone

In VS Code's Explorer:

  1. Right-click pipeline (inside src/) → New File → name it logging_config.py.
  2. Configure structlog for your capstone, the same shape as this module's lab — JSON output, a TimeStamper, merge_contextvars.
  3. Add structlog to pyproject.toml's dependencies.

Step 3: Add a run ID to your ingestion path

Wherever your capstone currently fetches or processes records (from Modules 2-4's work), bind a run_id once at the start, and log external_id (never the full raw record) at each meaningful step — fetched, validated, upserted, dead-lettered.

Step 4: Prove it against a real failure — the one mandatory terminal step

Open the integrated terminal, confirm your venv is active, and force a real failure using the mock API's chaos flags — the same ones from Step 1's infrastructure:

bash
python3 -c "
import urllib.request
try:
    urllib.request.urlopen('http://localhost:8000/records?date=2026-07-01&page=1&force_timeout=true', timeout=2)
except Exception as e:
    print('Confirmed a real failure mode:', type(e).__name__)
"

Then check that if your pipeline hit this same failure, your logs would tell you exactly what happened, which record, and which run — without you needing to look at source code or reproduce it again.

Step 5: Commit and push through VS Code's Source Control panel

  1. Click the Source Control icon in the sidebar.
  2. Confirm .venv is not listed under Changes.
  3. Stage, commit with a message like Module 6: structured logging with run ID, and click Commit.
  4. Click Sync Changes to push to GitHub.
  5. Confirm the changes appear on GitHub.

Check row 6 off your SPEC.md checklist. Three to go.

Before you close for the day:

bash
docker compose stop

Interview drill

Every question below follows the same pattern. First, the question. Then, what the interviewer wants to hear. Then, a junior engineer's answer. Then, a strong senior answer.

Recall

Question: "What does a run ID actually give you that a normal log message doesn't? Why bind it once instead of passing it to every log call by hand?"

What the interviewer wants to hear: a concrete explanation of what a run ID enables — correlating a full sequence of events — not just "it's an ID for the run."

Junior answer: "A run ID identifies which run something belongs to. You bind it once so you don't have to type it every time."

(Technically true but doesn't explain the actual value — what becomes possible with a run ID that wasn't possible before.)

Senior answer: "Without a run ID, if you're looking at a shared log stream with many pipeline runs interleaved, there's no way to isolate 'everything that happened during this one specific run' — you're stuck guessing from timestamps or manually correlating. Binding a run ID once at the start means every log line from that run automatically carries it, so you can filter a real log aggregation tool down to exactly one run's full story, in order. Binding it once instead of passing it explicitly to every call also matters practically — it means nobody can forget to include it on some new log line added later; it's attached at the source, not something every future caller has to remember."

Debugging

Question: shown as a real snippet and incident story, with no explanation yet:

python
import structlog

logger = structlog.get_logger()

def process_cdr(record: dict) -> None:
    logger.info("cdr_received", record_id=record["id"], carrier=record["carrier"])

    try:
        validated = validate_cdr(record)
    except ValidationError as e:
        print(f"Validation failed for record: {record}, error: {e}")
        raise

    enriched = enrich_with_billing(validated)
    logger.info("cdr_processed", record_id=record["id"])

"This service uses structlog everywhere — except one line. A customer complained that their call records, including the phone numbers of who they called, showed up in a shared log aggregation tool that many engineers across the company can search. Where's the leak, and why does it matter that it's this specific line and not the others?"

What the interviewer wants to hear: identifying the exact line, explaining precisely why it's worse than a normal unstructured log — it dumps the full raw record — and connecting this to why error handlers are a common regression point.

Junior answer: "The print statement should probably be a logger.error call instead, to match the rest of the file."

(Correctly spots the inconsistency, but doesn't explain what's actually being leaked, or why this specific location is dangerous.)

Senior answer: "The print() in the except block bypasses structlog entirely, and dumps the full raw record — including whatever PII the CDR contains, phone numbers, likely call duration, possibly location data — as unstructured text straight to stdout, which flows into the same searchable log aggregation as everything else. The two logger.info calls are fine — they log specific, chosen fields, record_id and carrier, not the raw payload. What makes this specific line dangerous is exactly where it sits: error handlers are often the least-reviewed part of a codebase, and they're exactly where someone extending this function — human or AI — is likely to reach for a quick print(record) 'just to see what's in it,' without applying the same field-discipline as the rest of the file. The fix is logger.error(...) with explicit, chosen fields — not the raw record — and if the raw payload is genuinely needed for debugging, redacting or hashing sensitive fields first. I'd also want a lint rule or pre-commit hook that flags bare print() calls in a codebase that's standardized on structured logging, so this can't quietly slip back in."

AI-review

Question: shown this diff, with no explanation yet:

diff
      try:
          send_confirmation_email(order_id, order["customer_email"], order["total"])
          logger.info("email_send_succeeded", order_id=order_id)
+     except MalformedResponseError as e:
+         print(f"Malformed response for order: {order}, error: {e}")
+         raise
      except Exception as e:
          logger.error("email_send_failed", order_id=order_id, error=str(e))

What the interviewer wants to hear: recognizing the print() as a structured-logging regression, and specifically identifying that it leaks the full order object, including customer_email.

Junior answer: "This should probably use logger.error instead of print, to be consistent with the rest of the code."

(Correctly flags the inconsistency but doesn't identify the actual data being leaked, which is the more serious problem.)

Senior answer: "Two separate problems here, and the second one matters more than the first. First, yes — print() bypasses structlog entirely, breaking the structured-logging convention the rest of this file follows correctly. But look closer at what's inside the f-string — {order} is the entire raw order dictionary, which includes customer_email. That's a PII leak, introduced in exactly the kind of place this tends to happen — a new error-handling branch, added without matching the file's existing discipline. I'd tell the assistant explicitly: use logger.error(...), and only log order_id — the same field every other log line in this file already uses — not the raw order object. This is worth flagging as a pattern to watch for generally: new error-handling code is exactly where structured-logging regressions tend to sneak in, so it's worth reviewing those paths with extra care, not less."

Judgment

Interviewer: "You're the on-call engineer for a telecom platform processing call detail records for billing. A customer support team asks if they can get direct log access to a shared aggregation tool, to speed up resolving billing disputes — right now they have to file a ticket and wait for an engineer to pull specific records. Your tech lead is inclined to say yes, since it would clearly speed up support. What do you say?"

Candidate (asking first): "Before I answer — what's currently being logged for each call record? Specifically, do the logs include the actual phone numbers involved, or just an internal record ID?"

Interviewer: "Good question — right now, yes, the logs include the full phone numbers of both parties on the call, along with call duration. That's actually part of why support wants direct access; the ticket-and-wait process is slow specifically because engineers have to go pull that same information for them."

Candidate (first answer): "Then I'd push back on giving broad log access as the solution, even though I understand the underlying need is real. The problem isn't really 'support needs faster access to logs' — it's 'support needs faster access to call metadata for billing disputes.' Those aren't the same thing, and solving it by exposing the current logs directly means giving broad access to full phone numbers and call details logged for an entirely different purpose — debugging — to a much wider audience than engineers troubleshooting a specific incident."

Interviewer (pushback): "But engineers already have access to this same data in the logs today. Why is it worse for support to have it too?"

Candidate (round 1): "Scale and purpose both matter here, not just who technically has access already. Engineers accessing logs to debug a specific incident is narrow, occasional, and tied to a real technical need in the moment. Giving an entire support team standing access to search full call records, whenever they want, for any customer, is a much larger and more routine exposure — more people, more often, for a purpose the logs were never designed around. I'd also point out that 'a smaller group already has some access' isn't actually a justification for expanding it — if anything, it's worth asking whether logging full phone numbers by default was the right call for engineers either."

Interviewer (second pushback): "So what would you actually propose instead, given support has a legitimate need here?"

Candidate (round 2): "I'd propose separating the two concerns instead of solving both through log access. First, fix the actual logging — call records should be logged with an internal record ID, not raw phone numbers, the same discipline you'd want in any structured logging setup. Second, build support a purpose-built tool or view that looks up billing-relevant details by record ID or account, backed by the actual billing system, not the debug logs — with access controls and an audit trail appropriate for customer PII, not general log search. That gives support faster access to what they actually need, without needing every call's phone numbers sitting in a search tool a much larger group can query."

Interviewer (final challenge): "That sounds like a bigger project than just flipping on log access this week. Convince me it's worth the extra time."

Candidate (final defense): "It's worth it because the two options aren't actually solving the same problem at the same risk level. Log access this week is fast, but it's fast specifically because it skips the part where PII exposure gets properly controlled — and once broad access exists, it's much harder to walk back than it would have been to not grant it in the first place. The purpose-built approach takes longer, but it actually matches the tool to the real need: support gets faster resolution, on the specific data they need, with real access controls — instead of a shortcut that happens to work today but creates a real compliance and privacy problem the moment anyone asks how many people can currently search customers' call records."

Model strong answer — a single answer, given upfront:

Output / Note

"I'd want to know first whether the current logs include raw phone numbers or just an internal record ID — assuming they include the raw numbers, I'd push back on granting broad log access, even though I understand the underlying need is real. The actual problem isn't 'support needs log access,' it's 'support needs faster access to billing-relevant call metadata' — and solving that by exposing today's debug logs means giving a much larger group standing access to full phone numbers and call details that were only ever logged for engineering debugging. I'd propose two things instead: first, fix the logging itself so call records are identified by an internal record ID, not raw phone numbers — good practice regardless of this request. Second, build a purpose-built lookup tool for support, backed by the actual billing system, with access controls and an audit trail appropriate for customer PII — not general log search. That's more work than flipping on access this week, but it actually solves support's real problem instead of trading it for a much harder to reverse privacy exposure."