Learning Hub

How to Debug a Production-Only Bug With Correlation IDs and Structured Logging in Python

Learn how to diagnose a bug that only happens in production using request correlation IDs and structured JSON logging in a FastAPI app, including a real concurrency mistake to avoid and a fail-fast...

July 28, 2026 18 Min Read
56

A bug report comes in: one customer’s order total is wrong, or their request just fails. You open the app on your own machine, run the exact same steps, and everything works. Your teammate tries too, also fine. The automated tests are green. This is one of the most frustrating situations in software: a bug that is real for the customer but invisible to everyone trying to reproduce it, because it only happens in production.

Table Of Content

Most of the time this is not a mystery bug in your business logic. It is a difference between your environment and production: a missing environment variable, a config value that defaults differently, a timing window that only opens under real concurrent traffic. The code is the same in both places; the environment is not. And when the default logging in most frameworks gives you a generic “Internal Server Error” with no context about which customer, which request, or which environment setting caused it, you are left guessing.

This tutorial teaches you how to close that gap using two techniques: a correlation ID (also called a request ID) and structured logging. A correlation ID is a unique value generated once per incoming request and attached to every log line produced while handling it, so you can pull one request’s entire story out of a sea of concurrent traffic just by searching for that ID. Structured logging means writing log lines as machine-readable data, typically JSON, with named fields like request_id or customer_id, instead of a free-form sentence that a human has to parse by eye. Together they turn “something failed somewhere” into “here is the exact request, the exact customer, and the exact exception.”

You will build a small FastAPI order-pricing service, deliberately reproduce a bug that only shows up under a production-like configuration, make a very common mistake while adding request correlation, watch that mistake fail under real concurrent load, fix it properly, and then use the improved logging to pinpoint and permanently fix the original bug. Every command in this guide was run on a real machine while writing it, and every log line and terminal output shown is copied from that real run, not invented.

What You Will Build

The example app is a small order-pricing API with one endpoint that computes an order total and applies a loyalty discount for VIP customers. The discount percentage is read from an environment variable, which is a completely ordinary and realistic pattern (12-factor apps read configuration from the environment precisely so the same code can run unchanged in development, staging, and production). The bug: this variable is set in the developer’s shell but never set in the “production” environment you will simulate, so VIP customers fail while everyone else is fine, a classic hard-to-reproduce, environment-only bug.

You will work through five stages, in order:

  • Reproduce the bug with the app’s default logging, and see exactly how little it tells you.
  • Add a request correlation ID the naive way, using an ordinary shared variable, and prove with a real concurrent test that this approach silently mixes up different requests’ IDs.
  • Fix the correlation ID using Python’s contextvars module, and confirm the same concurrent test now passes cleanly.
  • Switch to structured JSON logging that carries the correlation ID and business context on every line, and use it to instantly pinpoint the original bug.
  • Fix the root cause by validating configuration when the app starts instead of the first time a VIP customer happens to hit the broken code path, so this entire class of bug cannot reach production silently again.

Prerequisites

  • Python 3.10 or newer. This guide was written and tested against Python 3.11.15 on Ubuntu 26.04 LTS; the same code runs unmodified on macOS, Windows, and other Linux distributions.
  • Basic comfort with the command line and with reading Python. Some exposure to async/await is helpful but not required; the parts that matter for this tutorial are explained when they come up.
  • No external services, accounts, or API keys. Everything in this tutorial runs entirely on your own machine using two terminal windows.

Step 1: Create a Project and Install Dependencies

Start with an isolated virtual environment, so these packages do not collide with anything else on your machine:

# Context: a fresh project directory, Python 3.10+ already installed.
# Purpose: isolate this project's dependencies, then install the web framework, server, and HTTP client used throughout.
mkdir debug-demo && cd debug-demo
python3 -m venv venv
source venv/bin/activate
pip install fastapi uvicorn httpx

On Windows, activate the environment with venv\Scripts\activate instead of the source venv/bin/activate line above; everything else in this guide is identical.

Expected output: pip resolving and installing each package, ending in a Successfully installed ... line. This tutorial was tested against fastapi 0.140.13, uvicorn 0.51.0, and httpx 0.28.1. uvicorn is the server that actually runs a FastAPI app; httpx is only used later to fire concurrent test requests from a script, your app code itself does not need it.

Step 2: Build the Orders API and Reproduce a Bug You Can’t See Locally

Save the following as app.py. It is a deliberately ordinary FastAPI service: one endpoint, a hardcoded lookup of two customers standing in for a database, and a loyalty discount for VIP customers read from an environment variable.

import logging
import os

from fastapi import FastAPI

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger("orders")

app = FastAPI()

CUSTOMERS = {
    "cust_1": {"name": "Priya", "vip": False},
    "cust_2": {"name": "Marcus", "vip": True},
}


@app.get("/api/orders/{order_id}/total")
def get_order_total(order_id: str, customer_id: str, subtotal: float):
    customer = CUSTOMERS.get(customer_id)
    if customer is None:
        return {"error": "unknown customer"}

    total = subtotal
    if customer["vip"]:
        discount_percent = float(os.environ.get("LOYALTY_DISCOUNT_PERCENT"))
        total = subtotal * (1 - discount_percent / 100)

    return {
        "order_id": order_id,
        "customer": customer["name"],
        "subtotal": subtotal,
        "total": round(total, 2),
    }

Run it the way you would on your own development machine, with the discount configured in your shell:

# Context: debug-demo/ with venv activated, app.py from above saved in this directory.
# Purpose: start the app the way a developer's machine typically runs it, with config set in the shell.
export LOYALTY_DISCOUNT_PERCENT=10
uvicorn app:app --host 127.0.0.1 --port 8001

From a second terminal, call the endpoint for a regular customer and then a VIP customer:

curl "http://127.0.0.1:8001/api/orders/ord_100/total?customer_id=cust_1&subtotal=50"
curl "http://127.0.0.1:8001/api/orders/ord_101/total?customer_id=cust_2&subtotal=200"

Expected output:

{"order_id":"ord_100","customer":"Priya","subtotal":50.0,"total":50.0}
{"order_id":"ord_101","customer":"Marcus","subtotal":200.0,"total":180.0}

Both work. Marcus, a VIP, gets his 10 percent discount (200 becomes 180). This is the version you would test locally and ship with confidence.

Now Simulate Production

Stop the server (Ctrl+C), unset the variable to simulate a deployment that forgot to configure it, a genuinely common way for this class of bug to reach production, and start the app again:

# Context: same directory, same venv.
# Purpose: simulate a production environment where LOYALTY_DISCOUNT_PERCENT was never configured.
unset LOYALTY_DISCOUNT_PERCENT
uvicorn app:app --host 127.0.0.1 --port 8001

Run the exact same two requests again:

curl -w "\nHTTP_STATUS:%{http_code}\n" "http://127.0.0.1:8001/api/orders/ord_200/total?customer_id=cust_1&subtotal=75"
curl -w "\nHTTP_STATUS:%{http_code}\n" "http://127.0.0.1:8001/api/orders/ord_201/total?customer_id=cust_2&subtotal=300"

Expected output:

{"order_id":"ord_200","customer":"Priya","subtotal":75.0,"total":75.0}
HTTP_STATUS:200
Internal Server Error
HTTP_STATUS:500

Priya, a non-VIP customer, still works fine. Marcus fails with nothing but “Internal Server Error.” This is exactly the bug from the introduction: it depends on both the customer (VIP or not) and the environment (whether the variable is set), so a support engineer testing with a random non-VIP account, or a developer testing locally with the variable set, will never see it.

Look at the server’s own terminal. Uvicorn does log a full Python traceback (TypeError: float() argument must be a string or a real number, not 'NoneType', pointing at the float(os.environ.get(...)) line), so the failure is not completely invisible on the server. But notice what is missing from that traceback: no customer ID, no order ID, and if ten requests were failing at once, no way to tell which log lines belong to which request. In a real production system with dozens of concurrent requests and a log aggregator collecting output from many server instances, this traceback is a needle you cannot even search for, because it has no unique handle. That is the actual problem this tutorial solves: not the missing variable itself, but the lack of any way to connect a customer’s specific complaint to a specific line in a specific request’s execution.

Step 3: Add Request Correlation IDs (and a Mistake to Avoid)

The fix people usually reach for first is to generate a unique ID for each incoming request and stamp it onto every log line that request produces. Then, when a customer reports a problem, you ask for (or already have, if you return it in error responses) that ID and search your logs for exactly it, instantly getting every log line from that one request and nothing else, even if a thousand other requests logged something in the same second.

A Naive First Attempt (and Why It Breaks Under Concurrency)

The obvious way to “remember” the current request’s ID is a plain variable that a middleware sets at the start of each request, and that a logging filter reads from when formatting each line. Save this as step_bad.py:

import asyncio
import logging
import os
import uuid

from fastapi import FastAPI, Request

# BAD: a single shared variable for "the current request ID".
current_request_id = None


class RequestIdFilter(logging.Filter):
    def filter(self, record):
        record.request_id = current_request_id or "-"
        return True


logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(levelname)s [req=%(request_id)s] %(message)s",
)
logger = logging.getLogger("orders")
logger.addFilter(RequestIdFilter())

app = FastAPI()

CUSTOMERS = {
    "cust_1": {"name": "Priya", "vip": False},
    "cust_2": {"name": "Marcus", "vip": True},
}


@app.middleware("http")
async def add_request_id(request: Request, call_next):
    global current_request_id
    current_request_id = str(uuid.uuid4())[:8]
    logger.info("Started %s %s", request.method, request.url.path)
    response = await call_next(request)
    return response


@app.get("/api/orders/{order_id}/total")
async def get_order_total(order_id: str, customer_id: str, subtotal: float):
    customer = CUSTOMERS.get(customer_id)
    if customer is None:
        return {"error": "unknown customer"}

    logger.info("Looked up customer %s for order %s", customer_id, order_id)
    await asyncio.sleep(0.3)  # simulate a downstream pricing-service call

    total = subtotal
    if customer["vip"]:
        discount_percent = float(os.environ.get("LOYALTY_DISCOUNT_PERCENT"))
        total = subtotal * (1 - discount_percent / 100)

    logger.info("Computed total %.2f for order %s", total, order_id)
    return {
        "order_id": order_id,
        "customer": customer["name"],
        "subtotal": subtotal,
        "total": round(total, 2),
    }

The await asyncio.sleep(0.3) stands in for a real downstream call this endpoint might make, a pricing service, a database, another microservice, anything that takes a moment and involves an await. This detail matters for what happens next. FastAPI’s @app.middleware("http") decorator and the call_next pattern used here are the officially documented way to add middleware, taking the incoming request, running code before and after the rest of the app handles it.

Start this version with the discount configured, so we are testing the concurrency behavior in isolation from the earlier bug:

export LOYALTY_DISCOUNT_PERCENT=10
uvicorn step_bad:app --host 127.0.0.1 --port 8001

Now fire two requests at the same time instead of one after another. A plain sequence of curl commands will not reveal this bug, since each finishes before the next starts; you need real overlap. Save this as fire_concurrent.py and run it from a second terminal:

import asyncio

import httpx


async def call(client, order_id, customer_id, subtotal):
    r = await client.get(
        f"http://127.0.0.1:8001/api/orders/{order_id}/total",
        params={"customer_id": customer_id, "subtotal": subtotal},
    )
    print(order_id, "->", r.status_code, r.text)


async def main():
    async with httpx.AsyncClient(timeout=10) as client:
        await asyncio.gather(
            call(client, "ord_A", "cust_1", 40),
            call(client, "ord_B", "cust_1", 999),
        )


if __name__ == "__main__":
    asyncio.run(main())

python3 fire_concurrent.py

Expected output, in the server’s terminal (real captured output, not simulated):

2026-07-28 14:44:27,380 INFO [req=01726ff2] Started GET /api/orders/ord_A/total
2026-07-28 14:44:27,397 INFO [req=01726ff2] Looked up customer cust_1 for order ord_A
2026-07-28 14:44:27,397 INFO [req=3ce86fac] Started GET /api/orders/ord_B/total
2026-07-28 14:44:27,397 INFO [req=3ce86fac] Looked up customer cust_1 for order ord_B
2026-07-28 14:44:27,699 INFO [req=3ce86fac] Computed total 40.00 for order ord_A
2026-07-28 14:44:27,699 INFO [req=3ce86fac] Computed total 999.00 for order ord_B

Look closely at the last two lines. Both show req=3ce86fac, request B’s ID, even though the first line is clearly about order ord_A. Request A’s own ID, 01726ff2, has vanished from its own final log line. Here is what happened: request A logged “Started” and “Looked up customer” with its correct ID, then hit await asyncio.sleep(0.3) and paused. While A was paused, request B started, immediately overwrote the single shared current_request_id variable with its own ID, and ran to completion. When A finally woke up and logged its “Computed total” line, it read the module-level variable again, and by then B had already overwritten it. Both requests are, from Python’s point of view, running on the very same thread, taking turns each time either one hits an await; a single shared variable has no idea which turn is currently “yours.”

This is not a contrived edge case. Any endpoint that does real work, a database query, an HTTP call to another service, a file read, contains an await, and any production service handles more than one request at a time. A shared variable for per-request state will eventually attribute one request’s log lines to a different request’s ID, which is worse than having no correlation ID at all: it looks trustworthy while quietly lying.

The Correct Fix With contextvars

Python’s standard library has a purpose-built tool for exactly this problem: contextvars. The official documentation states its purpose directly: “Context managers that have state should use Context Variables instead of threading.local() to prevent their state from bleeding to other code unexpectedly, when used in concurrent code,” and confirms that “Context variables are natively supported in asyncio and are ready to be used without any extra configuration.” Concretely, a contextvars.ContextVar gives each asyncio task, in FastAPI’s case, each in-flight request, its own private copy of the value, instead of one value shared by everyone.

Save this as step_fixed.py, changing only how the request ID is stored and read:

import asyncio
import logging
import os
import uuid
from contextvars import ContextVar

from fastapi import FastAPI, Request

# GOOD: contextvars.ContextVar is task-local under asyncio, each request's
# asyncio Task gets its own isolated copy instead of sharing one variable.
request_id_var: ContextVar[str] = ContextVar("request_id", default="-")


class RequestIdFilter(logging.Filter):
    def filter(self, record):
        record.request_id = request_id_var.get()
        return True


logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(levelname)s [req=%(request_id)s] %(message)s",
)
logger = logging.getLogger("orders")
logger.addFilter(RequestIdFilter())

app = FastAPI()

CUSTOMERS = {
    "cust_1": {"name": "Priya", "vip": False},
    "cust_2": {"name": "Marcus", "vip": True},
}


@app.middleware("http")
async def add_request_id(request: Request, call_next):
    token = request_id_var.set(str(uuid.uuid4())[:8])
    try:
        logger.info("Started %s %s", request.method, request.url.path)
        response = await call_next(request)
        return response
    finally:
        request_id_var.reset(token)


@app.get("/api/orders/{order_id}/total")
async def get_order_total(order_id: str, customer_id: str, subtotal: float):
    customer = CUSTOMERS.get(customer_id)
    if customer is None:
        return {"error": "unknown customer"}

    logger.info("Looked up customer %s for order %s", customer_id, order_id)
    await asyncio.sleep(0.3)  # simulate a downstream pricing-service call

    total = subtotal
    if customer["vip"]:
        discount_percent = float(os.environ.get("LOYALTY_DISCOUNT_PERCENT"))
        total = subtotal * (1 - discount_percent / 100)

    logger.info("Computed total %.2f for order %s", total, order_id)
    return {
        "order_id": order_id,
        "customer": customer["name"],
        "subtotal": subtotal,
        "total": round(total, 2),
    }

request_id_var.set(...) returns a Token, and request_id_var.reset(token) restores the previous value once the request finishes; wrapping that in try/finally guarantees the reset happens even if call_next raises. Restart the server with this version (uvicorn step_fixed:app --host 127.0.0.1 --port 8001, discount variable still set) and rerun the identical concurrent test:

python3 fire_concurrent.py

Expected output (real captured output):

2026-07-28 14:44:48,416 INFO [req=02b7ef85] Started GET /api/orders/ord_A/total
2026-07-28 14:44:48,433 INFO [req=02b7ef85] Looked up customer cust_1 for order ord_A
2026-07-28 14:44:48,433 INFO [req=42734e88] Started GET /api/orders/ord_B/total
2026-07-28 14:44:48,434 INFO [req=42734e88] Looked up customer cust_1 for order ord_B
2026-07-28 14:44:48,734 INFO [req=02b7ef85] Computed total 40.00 for order ord_A
2026-07-28 14:44:48,734 INFO [req=42734e88] Computed total 999.00 for order ord_B

Every line about ord_A now consistently shows 02b7ef85, and every line about ord_B shows 42734e88, all the way through, even though both requests were paused and resumed on the same event loop in between. That is the fix confirmed under the exact same race condition that broke the naive version.

Step 4: Make Logs Structured (JSON) and Correlate the Original Bug

A correlation ID only helps if you can actually search by it, and by the other details of a request, quickly. Free-form text log lines like "Computed total 40.00 for order ord_A" are fine for a human reading one terminal, but painful to filter, aggregate, or alert on once you have many server instances shipping logs to a central place. Structured logging solves this by writing each log line as data, in this case JSON, with named fields, so any log processor can query it directly: “show me every line where request_id equals this value” or “count errors grouped by customer_id.”

Extend the fixed version with a JSON formatter and attach business context, customer_id and order_id, to each log call using the standard library’s built-in extra parameter, documented as one of the keyword arguments every logging call accepts to merge additional fields onto the resulting LogRecord. Save this as step_structured.py:

import asyncio
import json
import logging
import os
import uuid
from contextvars import ContextVar

from fastapi import FastAPI, Request
from fastapi.responses import JSONResponse

request_id_var: ContextVar[str] = ContextVar("request_id", default="-")


class RequestIdFilter(logging.Filter):
    def filter(self, record):
        record.request_id = request_id_var.get()
        return True


class JsonFormatter(logging.Formatter):
    def format(self, record):
        payload = {
            "timestamp": self.formatTime(record, "%Y-%m-%dT%H:%M:%S"),
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
            "request_id": getattr(record, "request_id", "-"),
        }
        for key in ("customer_id", "order_id"):
            value = getattr(record, key, None)
            if value is not None:
                payload[key] = value
        if record.exc_info:
            payload["exception"] = self.formatException(record.exc_info)
        return json.dumps(payload)


handler = logging.StreamHandler()
handler.setFormatter(JsonFormatter())
handler.addFilter(RequestIdFilter())

logger = logging.getLogger("orders")
logger.setLevel(logging.INFO)
logger.addHandler(handler)
logger.propagate = False

app = FastAPI()

CUSTOMERS = {
    "cust_1": {"name": "Priya", "vip": False},
    "cust_2": {"name": "Marcus", "vip": True},
}


@app.middleware("http")
async def add_request_id(request: Request, call_next):
    token = request_id_var.set(str(uuid.uuid4())[:8])
    try:
        logger.info("Started %s %s", request.method, request.url.path)
        response = await call_next(request)
        return response
    finally:
        request_id_var.reset(token)


@app.get("/api/orders/{order_id}/total")
async def get_order_total(order_id: str, customer_id: str, subtotal: float):
    customer = CUSTOMERS.get(customer_id)
    if customer is None:
        return {"error": "unknown customer"}

    ctx = {"customer_id": customer_id, "order_id": order_id}
    logger.info("Looked up customer %s for order %s", customer_id, order_id, extra=ctx)
    await asyncio.sleep(0.3)  # simulate a downstream pricing-service call

    total = subtotal
    if customer["vip"]:
        try:
            discount_percent = float(os.environ.get("LOYALTY_DISCOUNT_PERCENT"))
        except (TypeError, ValueError):
            logger.error(
                "Failed to read LOYALTY_DISCOUNT_PERCENT while pricing order %s for VIP customer %s",
                order_id,
                customer_id,
                exc_info=True,
                extra=ctx,
            )
            return JSONResponse(
                status_code=500,
                content={"error": "internal error", "request_id": request_id_var.get()},
            )
        total = subtotal * (1 - discount_percent / 100)

    logger.info("Computed total %.2f for order %s", total, order_id, extra=ctx)
    return {
        "order_id": order_id,
        "customer": customer["name"],
        "subtotal": subtotal,
        "total": round(total, 2),
    }

Two things changed beyond formatting. First, the handler catches the specific TypeError/ValueError that a missing or malformed environment variable produces, logs it with exc_info=True so the full traceback is preserved inside the structured exception field instead of being lost, and returns a proper JSON error body that includes the request_id, so a customer or a support ticket can hand that ID straight back to you. Second, every log call in the request path now passes extra=ctx, attaching customer_id and order_id automatically.

Restart in the “production” configuration (variable unset) and repeat the original two requests from Step 2:

unset LOYALTY_DISCOUNT_PERCENT
uvicorn step_structured:app --host 127.0.0.1 --port 8001

curl "http://127.0.0.1:8001/api/orders/ord_400/total?customer_id=cust_1&subtotal=80"
curl "http://127.0.0.1:8001/api/orders/ord_401/total?customer_id=cust_2&subtotal=500"

Expected output, client side:

{"order_id":"ord_400","customer":"Priya","subtotal":80.0,"total":80.0}
{"error":"internal error","request_id":"a0dfece8"}

Expected output, server log for the failing request (real captured output, pretty-printed here for readability with the traceback’s file path shortened; the log line itself is actually printed as a single-line JSON object):

{
  "timestamp": "2026-07-28T14:45:56",
  "level": "ERROR",
  "logger": "orders",
  "message": "Failed to read LOYALTY_DISCOUNT_PERCENT while pricing order ord_401 for VIP customer cust_2",
  "request_id": "a0dfece8",
  "customer_id": "cust_2",
  "order_id": "ord_401",
  "exception": "Traceback (most recent call last):\n  File \"step_structured.py\", line 79, in get_order_total\n    discount_percent = float(os.environ.get(\"LOYALTY_DISCOUNT_PERCENT\"))\nTypeError: float() argument must be a string or a real number, not 'NoneType'"
}

Compare this to Step 2’s bare traceback. Support gets a request_id to hand to engineering. Engineering searches logs for exactly that ID and, in one line, sees the customer, the order, the precise exception, and the full traceback, all without cross-referencing separate log streams or guessing which of many concurrent tracebacks belongs to which complaint. That is the entire value of correlation IDs plus structured logging: not preventing the bug, but collapsing the time it takes to find it from “reproduce it yourself” to “read one line.”

Step 5: Fix the Root Cause With Fail-Fast Configuration Validation

Better logging made this bug fast to diagnose, but the actual fix is to stop it from reaching a customer at all. The relevant principle is “fail fast”: if a service cannot run correctly without a piece of configuration, it should refuse to start the moment that is discovered, not wait until some specific request path happens to need it. A deployment that starts “successfully” but is silently broken for one category of customer is worse than a deployment that fails its health check immediately with a clear reason.

Move the environment variable lookup out of the request handler and into a startup-time check. Save this as step_final.py:

import asyncio
import json
import logging
import os
import uuid
from contextvars import ContextVar

from fastapi import FastAPI, Request

request_id_var: ContextVar[str] = ContextVar("request_id", default="-")


class RequestIdFilter(logging.Filter):
    def filter(self, record):
        record.request_id = request_id_var.get()
        return True


class JsonFormatter(logging.Formatter):
    def format(self, record):
        payload = {
            "timestamp": self.formatTime(record, "%Y-%m-%dT%H:%M:%S"),
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
            "request_id": getattr(record, "request_id", "-"),
        }
        for key in ("customer_id", "order_id"):
            value = getattr(record, key, None)
            if value is not None:
                payload[key] = value
        if record.exc_info:
            payload["exception"] = self.formatException(record.exc_info)
        return json.dumps(payload)


handler = logging.StreamHandler()
handler.setFormatter(JsonFormatter())
handler.addFilter(RequestIdFilter())

logger = logging.getLogger("orders")
logger.setLevel(logging.INFO)
logger.addHandler(handler)
logger.propagate = False


def load_loyalty_discount_percent() -> float:
    raw = os.environ.get("LOYALTY_DISCOUNT_PERCENT")
    if raw is None:
        raise RuntimeError(
            "Missing required environment variable LOYALTY_DISCOUNT_PERCENT. "
            "Set it to a number, for example: LOYALTY_DISCOUNT_PERCENT=10"
        )
    try:
        return float(raw)
    except ValueError as exc:
        raise RuntimeError(
            f"LOYALTY_DISCOUNT_PERCENT={raw!r} is not a valid number"
        ) from exc


# Fail fast: validate configuration at import time (app startup), not the
# first time a VIP customer happens to hit the endpoint.
LOYALTY_DISCOUNT_PERCENT = load_loyalty_discount_percent()

app = FastAPI()

CUSTOMERS = {
    "cust_1": {"name": "Priya", "vip": False},
    "cust_2": {"name": "Marcus", "vip": True},
}


@app.middleware("http")
async def add_request_id(request: Request, call_next):
    token = request_id_var.set(str(uuid.uuid4())[:8])
    try:
        logger.info("Started %s %s", request.method, request.url.path)
        response = await call_next(request)
        return response
    finally:
        request_id_var.reset(token)


@app.get("/api/orders/{order_id}/total")
async def get_order_total(order_id: str, customer_id: str, subtotal: float):
    customer = CUSTOMERS.get(customer_id)
    if customer is None:
        return {"error": "unknown customer"}

    ctx = {"customer_id": customer_id, "order_id": order_id}
    logger.info("Looked up customer %s for order %s", customer_id, order_id, extra=ctx)
    await asyncio.sleep(0.3)  # simulate a downstream pricing-service call

    total = subtotal
    if customer["vip"]:
        total = subtotal * (1 - LOYALTY_DISCOUNT_PERCENT / 100)

    logger.info("Computed total %.2f for order %s", total, order_id, extra=ctx)
    return {
        "order_id": order_id,
        "customer": customer["name"],
        "subtotal": subtotal,
        "total": round(total, 2),
    }

Try starting this version the way the broken “production” deployment did, with the variable unset:

unset LOYALTY_DISCOUNT_PERCENT
uvicorn step_final:app --host 127.0.0.1 --port 8001

Expected output (real captured output, file path shortened for readability):

File "step_final.py", line 64, in <module>
    LOYALTY_DISCOUNT_PERCENT = load_loyalty_discount_percent()
File "step_final.py", line 50, in load_loyalty_discount_percent
    raise RuntimeError(
RuntimeError: Missing required environment variable LOYALTY_DISCOUNT_PERCENT. Set it to a number, for example: LOYALTY_DISCOUNT_PERCENT=10

The server never starts. There is no partially-working deployment where some customers succeed and VIP customers silently 500; there is a deployment that fails immediately, with a message that names the exact missing variable and shows an example of a valid value. Whoever is deploying finds out in the first few seconds, from the deployment logs, not days later from a customer complaint.

Now start it correctly and confirm both customer types work:

export LOYALTY_DISCOUNT_PERCENT=10
uvicorn step_final:app --host 127.0.0.1 --port 8001

curl "http://127.0.0.1:8001/api/orders/ord_300/total?customer_id=cust_1&subtotal=60"
curl "http://127.0.0.1:8001/api/orders/ord_301/total?customer_id=cust_2&subtotal=250"

Expected output:

{"order_id":"ord_300","customer":"Priya","subtotal":60.0,"total":60.0}
{"order_id":"ord_301","customer":"Marcus","subtotal":225.0,"total":225.0}

Marcus’s 250 subtotal correctly becomes 225 with the 10 percent discount applied, and the server’s structured logs show both requests’ request_id, customer_id, and order_id cleanly separated, exactly as in Step 4, just with no error path left to reach.

Common Mistakes and Gotchas

  • Using a plain global variable, or a naive thread-local, for per-request state under asyncio. Step 3 reproduced the global-variable version of this mistake directly: any endpoint with an await in it can be paused and resumed while other requests run in between, and a single shared variable has no concept of “whose turn it is.” A threading.local() would not save you either, since a single Uvicorn worker runs its whole event loop, and therefore every concurrent request’s coroutine, on one OS thread; thread-local storage only isolates by thread, not by request. Always use contextvars.ContextVar for request-scoped state in async code.
  • Logging the exception message alone, like str(e), instead of the full traceback. A message such as "float() argument must be a string or a real number, not 'NoneType'" does not say which line raised it. Use logger.exception(...) (inside an except block) or pass exc_info=True as this tutorial did, so the complete traceback lands in your logs.
  • Putting sensitive data in structured fields. Because structured fields are so easy to search and export in bulk, never log full credit card numbers, passwords, auth tokens, or other personal data as a field value, even ones that seem convenient for debugging. Log an identifier (a customer ID, an order ID) instead of the sensitive value itself.
  • Logging at INFO level inside a hot loop. This tutorial’s endpoint logs twice per request, which is fine at normal traffic, but a log line inside a tight loop processing thousands of items will flood your logs and can measurably slow down the request. Reserve per-item logging for DEBUG level, or log a summary after the loop instead.
  • Always generating a brand-new request ID and never accepting one from upstream. If your service sits behind a load balancer, API gateway, or another internal service that already assigns a request ID (commonly forwarded as a header like X-Request-Id), read that value if present and only generate a new one when it is missing. Otherwise the same logical request gets a different, disconnected ID at every hop, defeating the purpose.

Verifying Everything Works End to End

  1. With the environment variable unset for step_final.py, starting uvicorn fails immediately with a RuntimeError that names LOYALTY_DISCOUNT_PERCENT specifically. The server process never starts, confirmed by the absence of the usual “Uvicorn running on …” line.
  2. With the variable set to a number, the server starts cleanly and both a non-VIP and a VIP request return 200 with the correct discount math applied.
  3. Every log line printed during those requests is valid JSON and contains a request_id field. If you have jq installed, pipe the server’s output through jq ., which pretty-prints each JSON object in a stream and errors on anything that is not valid JSON; otherwise, just eyeball the braces.
  4. Running fire_concurrent.py against step_final.py (or step_fixed.py) shows every log line for ord_A sharing one request_id, and every line for ord_B sharing a different one, with no mixing.
  5. Running fire_concurrent.py against step_bad.py specifically (the global-variable version), by contrast, reproduces the mixed-up IDs from Step 3, confirming you actually understand why the fix was necessary and not just that the final code happens to work.

If all five checks pass, you have a service that fails loudly and immediately when misconfigured instead of silently for one category of users, and that gives you, if a comparable bug ever does slip through, everything needed to diagnose it from a single correlated, structured log line instead of a bare traceback.

Next Steps

  • Read the official contextvars documentation in full; the same pattern used here for a request ID works for any other per-request state you want available deep inside your code without threading it through every function call.
  • Once correlation IDs and structured logs feel natural, look into distributed tracing (OpenTelemetry is the current vendor-neutral standard) for tracking a single request as it crosses multiple services, not just multiple log lines within one service.
  • Ship your JSON logs somewhere searchable instead of only a terminal, a hosted log platform or a self-hosted stack, so “search by request_id” becomes an actual query instead of scrolling through a file.
  • Add a startup check, the same fail-fast pattern from Step 5, for every other required environment variable your real services depend on, not just this tutorial’s single example.

Sources: freeCodeCamp: How to Diagnose Production Bugs When You Can’t Reproduce Them Locally (Manish Shivanandhan); Python documentation: contextvars, Context Variables; Python documentation: logging, Logging facility for Python; FastAPI documentation: Middleware. Featured image: photograph by Lewis Ngugi, CC0 1.0 Universal (public domain), via Wikimedia Commons.

Tags:

DebuggingFastAPILoggingObservabilityPython

Share

No Comment! Be the first one.

Leave a Reply

Your email address will not be published. Required fields are marked *

Related Posts