Module 10 · ~6 hours · Priority: High

Observability & Config

Make the running system visible: structured request logs, a health check that actually checks, and every secret and URL living in the environment rather than the source.

You cannot debug what you cannot see the framing

Your City Guide API works on your laptop, where you can put a print() anywhere and watch it appear. Nothing about that survives contact with a running system.

What
Observability is the practice of making a running program explain itself — what it did, how long it took, and what went wrong — without you attaching a debugger to it.
Where
Every server that anyone other than you depends on. It is the difference between "a user says it was slow yesterday" being answerable and being a shrug.
When
Now, before deployment — because the first time you need a log is always after the thing you needed to log has already happened.
How
Structured logs on every request, a health endpoint that tells the truth, and all config read from the environment at startup.

Picture the situation this module exists to prevent. Someone reports that saving a place to a list "sometimes takes ages". You cannot reproduce it. Your endpoint returns 200 every time you try. You have no record of what happened when it was slow, for whom, or how slow "ages" was. There is nothing to investigate — not because the problem is subtle, but because you never wrote anything down.

Three kinds of signal answer three different questions. People call them the three pillars, and the names get used loosely, so here is the plain version.

Logs say what happened. One entry per interesting event: this request arrived, this user failed to authenticate, this query raised. They are the highest-detail, highest-volume signal, and they are the only one that can tell you about a single specific occurrence rather than an average.

Metrics say how much and how often. Numbers aggregated over time: requests per second, error rate, 95th-percentile latency. They are cheap to store forever and they are what an alert fires on — but a metric can only ever tell you that the error rate tripled, never which requests failed or why.

Traces say where the time went. One request is broken into timed spans — 4ms in the handler, 210ms in a query, 90ms calling the identity service from Module 08 — so a slow request becomes a labelled bar chart instead of a mystery. Traces matter enormously once you have several services talking to each other, and almost not at all when you have one.

This module does logs and health properly and names the other two so you recognise them later. That is a deliberate ordering, not a shortcut: roughly ninety per cent of real debugging is reading logs, and a team with excellent logs and no tracing is in far better shape than the reverse.

Logging instead of printing

What
Python's built-in logging module: named loggers, severity levels, handlers that decide where records go, and formatters that decide how they look.
Where
The standard library, so it is already installed — and the same module every third-party package you depend on is already logging through.
When
Replace every print() in your City Guide project with it today, including the ones Module 00 told you to use freely while learning tracebacks.
How
log = logging.getLogger(__name__) at the top of each module, then log.info(...) where the print used to be.

Python ships a logging module and you should switch to it today. print() is not a lesser version of logging — it is a different thing that happens to also put text on a screen. Here is everything it lacks:

print()logging
SeverityNone. A crash and a debug note look identical.Five levels, filterable.
TimestampNone, unless you type one every time.Automatic, on every record.
SourceNone. Good luck finding which file printed it.Logger name, module, line number.
Turning it offEdit the code and redeploy.Change one environment variable.
Destinationstdout, always.Any handler: stdout, a file, a socket.
FormatWhatever you typed that day.One formatter for the whole app.

Four nouns and you know the whole module. A logger is the thing you call, named after your module. A level is the severity you attach. A handler decides where a record goes. A formatter decides what it looks like. Records flow from logger → handler → formatter → out.

import logging

log = logging.getLogger(__name__)   # __name__ is "app.routers.places"

log.debug("query params: %s", params)      # noisy detail, off in production
log.info("place created", extra={"place_id": place.id})
log.warning("rating out of range, clamped")
log.error("could not reach identity service")
log.critical("database connection pool exhausted")

Choosing the level is the part beginners get wrong, so be blunt about it. DEBUG is for things you want while developing and never in production. INFO is for events a healthy system produces — a request served, a user registered. WARNING means something is off but the request still succeeded; it is the level people over-use, and a warning nobody ever acts on is noise. ERROR means this operation failed and a human may need to know. CRITICAL means the process is in trouble as a whole. If everything is an ERROR, nothing is.

Why __name__ and not a string you made up. Loggers form a tree by dotted name. app.routers.places is a child of app.routers, which is a child of app, which is a child of the root. Because of that hierarchy you can turn the volume up on exactly one part of your codebase:

logging.getLogger("app.db").setLevel(logging.DEBUG)   # just the database layer
logging.getLogger("sqlalchemy.engine").setLevel(logging.INFO)  # see every SQL query

That second line is how you watch the ORM from Module 05 emit the actual SQL, which is exactly the tool for spotting the N+1 problem from Module 06 — sixty identical SELECTs scrolling past is very hard to miss. Hardcode the name as "places" instead of using __name__ and you lose all of this, because your logger is now an orphan sitting directly under the root.

  • Use %s placeholders, not f-strings. log.debug("params: %s", params) does not build the string at all if DEBUG is switched off. log.debug(f"params: {params}") formats it every time and then throws it away — on a hot path that is real waste.
  • log.exception(...) is the one to reach for inside an except block. It logs at ERROR level and attaches the full traceback automatically. log.error(str(e)) throws away the stack you actually needed.
  • Libraries log too, and by default you hear none of it. Configuring the root logger once, at startup, means SQLAlchemy, uvicorn, and your own code all come out through the same formatter in the same shape.
  • Configure logging in exactly one place. Scattered basicConfig calls silently do nothing after the first one, which produces the maddening bug where your formatter works when you run one file and not another.

Structured logging

This is the upgrade that makes logs useful rather than merely present, and it costs about thirty lines.

What
Every log line is a JSON object with named fields, instead of an English sentence with the values baked into the prose.
Where
Standard in every serious backend, because logs get shipped into a system that indexes fields and cannot parse sentences.
When
From your very first log line. Converting prose logs to structured ones later means rewriting every call site.
How
A custom logging.Formatter whose format() returns json.dumps(...). No third-party package needed.

Look at the same event written both ways.

# prose - readable by you, opaque to everything else
2026-03-11 09:14:22 INFO Request GET /places?neighbourhood=Soho took 412ms and returned 200 for user 91

# structured - one JSON object per line
{"ts": "2026-03-11T09:14:22.481+00:00", "level": "INFO", "logger": "app.request",
 "msg": "request", "method": "GET", "route": "/places", "status": 200,
 "duration_ms": 412.3, "user_id": 91}

The question is not which is nicer to read. It is: how do you find every request slower than 500ms that returned a 500, for one user, across two million lines? With the prose version you are writing a regular expression against a sentence whose wording changes the moment someone edits the string — and it will change, because took 412ms and took 1.2s are the same code path printing different units. With the structured version, duration_ms > 500 and status == 500 and user_id == 91 is a filter, and it keeps working when someone adds a field.

Here is the whole implementation. It uses only the standard library.

# app/logging_config.py
import json
import logging
import sys
from datetime import datetime, timezone

# Every attribute the logging module itself puts on a record. Anything on a
# record that is NOT in here came from your extra={...} and belongs in the JSON.
_BUILTIN = set(logging.LogRecord("", 0, "", 0, "", (), None).__dict__) | {
    "message", "asctime", "taskName",
}


class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "ts": datetime.fromtimestamp(
                record.created, timezone.utc
            ).isoformat(timespec="milliseconds"),
            "level": record.levelname,
            "logger": record.name,
            "msg": record.getMessage(),      # applies the %s arguments
        }
        for key, value in record.__dict__.items():
            if key not in _BUILTIN:
                payload[key] = value          # your extra={...} fields
        if record.exc_info:
            payload["exc"] = self.formatException(record.exc_info)
        return json.dumps(payload, default=str)   # default=str: never crash on a UUID


def setup_logging(level: str = "INFO") -> None:
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(JsonFormatter())

    root = logging.getLogger()
    root.handlers.clear()        # drop whatever uvicorn installed first
    root.addHandler(handler)
    root.setLevel(level.upper())

    # our own middleware logs every request, in JSON, with a duration.
    # uvicorn's plain-text access log would just duplicate it, badly.
    logging.getLogger("uvicorn.access").disabled = True

default=str earns its place: the day someone logs a UUID, a datetime, or a SQLAlchemy model, json.dumps raises TypeError — and a logging call that throws inside an error handler is a genuinely horrible bug to chase. Falling back to str() means the worst case is an ugly field, not a crash.

  • One line, one object, no newlines inside. Log shippers read line by line. A pretty-printed multi-line JSON blob is not structured logging, it is twelve broken records.
  • extra= keys become top-level fields, so keep the names stable. user_id in one place and userId in another means two columns that never join up.
  • Three key names are forbidden in extra: message, asctime, and anything already on a record such as name, args, or module. Python raises KeyError: "Attempt to overwrite 'name' in LogRecord". Prefix your own fields if you are unsure.
  • Write to stdout, never to a file your app opens itself. Rotation, retention, and shipping are the job of whatever runs your process. An app that manages its own log files fills a disk at 3am on a Sunday.
  • structlog is what most teams eventually install, and it is a good library — context binding, nicer developer output, the same JSON at the end. You do not need it, and writing the formatter yourself once means you will actually understand what it is doing for you.

Request logging middleware

What
A function that wraps every request — it runs before your endpoint, lets the endpoint run, then runs again after with the response in hand.
Where
Registered once on the FastAPI app. It applies to every route including ones you write next year.
When
Whenever behaviour must be identical for all endpoints: logging, timing, request ids, CORS, compression.
How
A Starlette BaseHTTPMiddleware subclass with an async dispatch method.

Middleware is the right shape here for one reason: you cannot forget it. Logging inside each endpoint means the endpoint you add in a hurry on a Friday is the one with no logs, which by a law of nature is the one that breaks.

# app/middleware.py
import logging
import time
import uuid

from starlette.middleware.base import BaseHTTPMiddleware

log = logging.getLogger("app.request")


class RequestLogMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request, call_next):
        # honour an incoming id if a caller already set one, else mint one
        request_id = request.headers.get("x-request-id") or str(uuid.uuid4())
        request.state.request_id = request_id      # endpoints can read this

        started = time.perf_counter()
        try:
            response = await call_next(request)
        except Exception:
            duration_ms = round((time.perf_counter() - started) * 1000, 2)
            log.exception("request failed", extra={
                "request_id": request_id,
                "method": request.method,
                "path": request.url.path,
                "status": 500,
                "duration_ms": duration_ms,
            })
            raise                                  # let FastAPI return the 500

        duration_ms = round((time.perf_counter() - started) * 1000, 2)
        route = request.scope.get("route")         # set once routing has happened

        log.info("request", extra={
            "request_id": request_id,
            "method": request.method,
            "path": request.url.path,              # /places/42
            "route": getattr(route, "path", request.url.path),   # /places/{place_id}
            "status": response.status_code,
            "duration_ms": duration_ms,
        })
        response.headers["X-Request-ID"] = request_id
        return response
# app/main.py
from fastapi import FastAPI

from app.config import get_settings
from app.logging_config import setup_logging
from app.middleware import RequestLogMiddleware

settings = get_settings()          # at import time - see the config section
setup_logging(settings.log_level)  # before the app object, so startup logs too

app = FastAPI(title="City Guide API")
app.add_middleware(RequestLogMiddleware)

time.perf_counter(), not time.time(). time.time() reads the wall clock, which can be adjusted backwards by NTP mid-request and hand you a negative duration. perf_counter() is monotonic — it only ever goes forward — and measuring an elapsed interval is precisely what it is for.

Log both path and route. path is what the client asked for (/places/42); route is the pattern that matched (/places/{place_id}). You need path to investigate one incident and route to aggregate — grouping by raw path gives you ten thousand groups of one, which tells you nothing about which endpoint is slow.

The request id is the point of the whole exercise. A UUID is generated per request, attached to every log line for that request, and returned in the X-Request-ID response header. That single field turns a haystack into an index:

client your API you, later ------ -------- ---------- POST /lists ------------> id = 7f3a-... log {request_id: 7f3a, msg: "request"} log {request_id: 7f3a, msg: "db error"} 500 + X-Request-ID: 7f3a <-- | `-- user reports it --------------------------> grep 7f3a app.log (every line, in order)

Without it, a user telling you "it failed around 2pm" leaves you reading every line logged in a ten-minute window, from every user, hoping to guess which one was theirs. With it, they paste eight characters and you have their exact request and everything it did. Accepting an inbound x-request-id rather than always minting a fresh one is what lets that same id follow a request from your API into the identity service from Module 08 — that is a trace, hand-rolled and cheap.

Never log these. Not once, not "temporarily". Passwords, password hashes, the Authorization header, JWTs from Module 07, session cookies, API keys, card numbers, and personal data you have no reason to keep. Logs are not private: they are written in plain text, copied to a log aggregator, indexed, retained for months, and read by people who will never touch your code. A token in a log is a token that has leaked.

The specific trap is not typing log.info(password) — nobody does that. It is logging a container. log.info("req", extra={"headers": dict(request.headers)}) ships every bearer token you have ever received. log.exception on a handler that took the request body writes the whole payload — passwords included — into the traceback context. Log named fields you chose deliberately: method, route, status, duration, user id. Never the whole object.
In other stacks: Node reaches for pino (fast, JSON by default) or winston, wired into Express as app.use(pinoHttp()) — same middleware shape, same fields, and pino emits exactly the kind of line you just built by hand. Django configures the identical standard-library logging module through a LOGGING dict in settings.py, and reads its environment with django-environ. Rails uses ActiveSupport::TaggedLogging or the semantic_logger gem, which tags every line in a request with a request id for you. The idea is completely portable; only the import lines change.

A health check that actually checks

What
An endpoint another machine calls on a timer to decide whether your process should receive traffic or be restarted.
Where
Compose healthchecks, load balancers, and every container orchestrator. Module 11 wires yours into docker-compose.yml.
When
Before anything runs your app automatically — which is any time it is not you typing uvicorn by hand.
How
Touch your real dependencies with a cheap query and a short timeout, and return 503 when they fail.

Almost every tutorial gives you this:

@app.get("/health")
def health():
    return {"ok": True}          # this is worse than having no health check

That is not a check, it is an assertion. It returns 200 while Postgres is down, while your connection pool is exhausted, while every single request is failing with a 500. And because it returns 200, the load balancer in front of you concludes you are healthy and keeps routing users to a broken process — possibly for hours, possibly after taking a working instance out of rotation to make room. With no health check at all, the platform at least knows it does not know. This one lies confidently, and confident lies are what break production.

# app/routers/health.py
import logging

from fastapi import APIRouter, Depends, Response, status
from sqlalchemy import text
from sqlalchemy.orm import Session

from app.db import get_db          # the dependency from Module 05

router = APIRouter(tags=["health"])
log = logging.getLogger(__name__)


@router.get("/health/live")
def liveness():
    """Am I running? Nothing else is checked, on purpose."""
    return {"status": "alive"}


@router.get("/health")
def readiness(response: Response, db: Session = Depends(get_db)):
    """Should traffic be sent to me right now?"""
    try:
        db.execute(text("SELECT 1"))
    except Exception as exc:
        log.error("readiness failed", extra={"dependency": "postgres",
                                             "error": str(exc)})
        response.status_code = status.HTTP_503_SERVICE_UNAVAILABLE
        return {"status": "unhealthy", "database": "unreachable"}
    return {"status": "ok", "database": "ok"}

SELECT 1 is the standard choice because it costs the database essentially nothing while still proving the entire path works: a connection was available in the pool, the socket is open, Postgres accepted a query and answered. Counting rows in places would prove the same thing and get slower every month.

The timeout is not optional. A health check that hangs is worse than one that fails, because the caller waits and then times out, which usually looks like a different problem entirely. Set the limit on the engine, once:

# app/db.py
engine = create_engine(
    settings.database_url,
    pool_pre_ping=True,                    # discard dead connections silently
    connect_args={"connect_timeout": 3},   # psycopg: give up after 3 seconds
)

Liveness versus readiness. These are two different questions, and merging them into one endpoint causes a specific, nasty failure.

LivenessReadiness
QuestionAm I running, or am I wedged?Should traffic come to me right now?
ChecksThe process only. No dependencies.Database, cache, anything you need to serve.
Failing meansKill and restart me.Stop sending requests, leave me alone.
Endpoint/health/live/health

Now the failure. Suppose you have one endpoint that checks the database, and you wire it up as the liveness probe. Postgres goes down for ninety seconds during a maintenance window. Your app is completely fine — it just cannot reach the database. The liveness probe fails, so the platform kills your container and starts a new one. The new one also cannot reach the database, so it is killed too. You now have a restart loop across every instance, no warm connection pools, and an outage that lasts far longer than the database blip that caused it — and your logs are useless, because each process dies before it writes anything interesting.

The correct behaviour is the opposite: readiness fails, traffic stops arriving, the processes sit patiently, and the moment Postgres returns they start passing again and traffic resumes on its own. Nothing restarted, nothing lost.

  • Liveness should be almost impossible to fail. If it can fail for a reason a restart will not fix, it is the wrong check. Deadlock and a full event loop are what it is for.
  • Check only what you need to serve a request. Marking yourself unhealthy because an unrelated downstream service is down converts their small outage into your total one.
  • Do not put the readiness endpoint behind authentication. The prober has no credentials. It also should not leak: return a status, not connection strings or version numbers.
  • Keep it out of your latency metrics. A probe every two seconds is thousands of trivially fast requests a day, and averaged in they will make your real endpoints look far faster than they are.

Config, done properly

Module 00 gave you a .env file and promised this module would do it properly. Here is the proper version, and the argument for why it matters more than it looks.

What
One typed, validated object holding every value that differs between your laptop and anywhere else, built from environment variables at startup.
Where
app/config.py, imported everywhere. After this section, os.getenv appears nowhere else in the project.
When
The moment you have more than about three settings, or the first time a missing variable causes a confusing runtime error.
How
A Pydantic BaseSettings class: field names map to environment variables, annotations give types, missing required fields stop the process.

The scattered version rots in a predictable way:

# the problem - spread across six files
DATABASE_URL = os.getenv("DATABASE_URL")                # None if unset. No error.
PORT = int(os.getenv("PORT", "8000"))                   # crashes if PORT="80 "
DEBUG = os.getenv("DEBUG")                              # "false" is a truthy string!
SECRET = os.getenv("JWT_SECRET", "changeme")            # a default that ships

Every line there is a real bug. DATABASE_URL silently becomes None and fails an hour later inside SQLAlchemy with a message about a NoneType. DEBUG is the string "false", which is truthy, so debug mode is on in production. And "changeme" is the default that signs your tokens the day someone forgets to set the variable — a default secret is not a convenience, it is a vulnerability with a friendly face.

pip install pydantic-settings
# app/config.py
import sys
from functools import lru_cache

from pydantic import Field, ValidationError
from pydantic_settings import BaseSettings, SettingsConfigDict


class Settings(BaseSettings):
    model_config = SettingsConfigDict(
        env_file=".env",        # local convenience only; ignored if the file is absent
        extra="ignore",         # your shell has hundreds of unrelated variables
    )

    # no default = required. The app will not start without it.
    database_url: str
    jwt_secret: str = Field(min_length=16)

    # defaults = optional, and typed: "8000" becomes the int 8000
    log_level: str = "INFO"
    port: int = 8000
    debug: bool = False
    access_token_ttl_minutes: int = 30


@lru_cache
def get_settings() -> Settings:
    try:
        return Settings()
    except ValidationError as exc:
        print("CONFIG ERROR - the app cannot start:", file=sys.stderr)
        for err in exc.errors():
            field = ".".join(str(p) for p in err["loc"])
            print(f"  {field}: {err['msg']}", file=sys.stderr)
        print("  See .env.example for every variable this app needs.",
              file=sys.stderr)
        raise SystemExit(1)

Field names are matched to environment variables case-insensitively, so database_url reads DATABASE_URL. lru_cache means the environment is read and validated exactly once per process, and every later get_settings() returns the same object — which also makes it trivially overridable in the pytest fixtures from Module 09 via get_settings.cache_clear().

The argument, and it is worth holding onto. An app that starts successfully with missing config and then fails on the first request at 3am is dramatically worse than one that refuses to start. The refusal happens at deploy time, in front of the person deploying, with a message naming the exact variable. The other failure happens hours later, in front of a user, as a 500 with a traceback about NoneType that names nothing useful — and by then the person who caused it has gone home. Fail fast, fail loudly, fail at the boundary. Configuration is the boundary.

Twelve-Factor, factor three: store config in the environment. The test it proposes is sharp — could you open-source your repository right now, this second, without leaking a single credential? If not, config is in your source. It follows that there is one codebase for every environment; what differs is only the values handed to the process. No if ENV == "production" branches, no config/production.py committed next to config/dev.py.

# .env.example  <- committed. Every variable, fake values, kept in sync.
DATABASE_URL=postgresql://user:password@localhost:5432/dbname
JWT_SECRET=generate-with-openssl-rand-hex-32
LOG_LEVEL=INFO
PORT=8000
DEBUG=false
ACCESS_TOKEN_TTL_MINUTES=30

.env is a local development convenience and nothing more. It exists so you do not type six export lines every morning, it stays in .gitignore, and it never travels anywhere. In a real deployment there is no .env file at all: whatever runs your container injects the values as actual environment variables, from a secret store you do not have to choose today. Your code cannot tell the difference and does not care — that indifference is the entire benefit. Module 11 passes them in through compose; the mechanism after that is somebody's product, and the interface is always the same six variables.

  • Required means no default. Resist adding one "so it runs". A default for a secret is how changeme ends up signing real tokens.
  • Types are validation. port: int rejects PORT=eighty at startup instead of at bind time; debug: bool understands false, 0, and no so the truthy-string bug cannot happen.
  • Never log the settings object. log.info("config: %s", settings) prints your JWT secret. If you want a startup summary, list the field names, not the values.
  • Import it, do not re-read it. One get_settings() at startup; pass the object or the value down. Calling os.getenv deep inside a function is how config drifts back out across the codebase.

Finding your slowest endpoint

Every request now logs a duration. That is data, and the tools from Module 00 are enough to interrogate it — no dashboard required.

What
Answering a performance question by aggregating your own log file on the command line.
Where
Your terminal, against the file you get by redirecting your server's stdout.
When
Before you optimise anything. Guessing which endpoint is slow is wrong often enough to waste days.
How
grep to select, jq to pull fields out of JSON, sort -rn and head to rank.

Your app writes to stdout, so you capture it with a redirect. tee shows you the stream and files it at the same time:

mkdir -p logs
uvicorn app.main:app --reload 2>&1 | tee logs/app.log

jq is a JSON processor and one of the best reasons to log JSON. On macOS brew install jq; on Debian or Ubuntu sudo apt install jq. Then:

# the ten slowest individual requests, worst first
grep '"logger": "app.request"' logs/app.log \
  | jq -r '[.duration_ms, .status, .method, .route] | @tsv' \
  | sort -rn | head -10

# average duration per route - the number that tells you where to look
grep '"logger": "app.request"' logs/app.log \
  | jq -r '"\(.route)\t\(.duration_ms)"' \
  | awk -F'\t' '{sum[$1]+=$2; n[$1]++}
                END {for (r in sum) printf "%8.1f  %5d  %s\n", sum[r]/n[r], n[r], r}' \
  | sort -rn

# how many of each status code came back
grep '"logger": "app.request"' logs/app.log | jq -r '.status' | sort | uniq -c

# everything that happened during one reported failure
grep '7f3a1c92' logs/app.log | jq .

No jq? The structure still helps, because the fields are quoted and named — something no prose log can promise:

grep -o '"duration_ms": [0-9.]*' logs/app.log \
  | cut -d' ' -f2 | sort -rn | head -5

Read the count column, not only the average. A route averaging 900ms that is called four times a day matters far less than one averaging 120ms called twenty thousand times — the second is where your capacity goes. This is also why you must group by route and not path: aggregating /places/{place_id} gives you one meaningful row instead of nine thousand rows of one request each.

Then hand it back to Module 03 and Module 06. You have a suspect endpoint. Turn on logging.getLogger("sqlalchemy.engine").setLevel(logging.INFO) and hit it once. If sixty near-identical SELECTs scroll past, that is the N+1 problem from Module 06 and the fix is eager loading, not an index. If it is one query and it is slow, copy that exact SQL into psql, put EXPLAIN ANALYZE in front of it, and read the plan the way Module 03 taught you — a sequential scan over places where you expected an index scan is your answer.

This is what a metrics system automates, not replaces. The pipeline above is one process, one file, and a moment in time. Metrics tooling does the same aggregation continuously, across every instance, keeps percentiles rather than averages, and alerts when a number moves. Averages hide the tail — a 40ms mean can contain a 4-second 99th percentile that a hundred users feel every hour. Learn to answer the question by hand first; the tooling then looks like a convenience instead of magic.

Build this

Target: the City Guide API from Module 09 now emits one JSON log line per request with a request id and a duration, exposes /health that returns 503 when Postgres is unreachable and /health/live that does not, reads every setting through one validated Settings object, and refuses to start when a required variable is missing.
  1. Write app/logging_config.py with JsonFormatter and setup_logging. Call it from app/main.py before the FastAPI() object is created.
  2. Write app/middleware.py with RequestLogMiddleware — method, path, route, status, duration_ms, request_id — and register it. Confirm the X-Request-ID response header appears.
  3. Write app/routers/health.py with /health (runs SELECT 1) and /health/live (does not). Add connect_timeout to the engine.
  4. Write app/config.py with Settings. Then delete every os.getenv in the project — grep -rn "os.getenv" app/ must come back empty — and update .env.example.
  5. Add an Environment variables section to README.md: a table of every variable, whether it is required, its default, and one line on what it does.
  6. Break it twice on purpose. First: comment out DATABASE_URL in .env and start the app — it must exit with a message naming that variable, not a traceback about None. Second: with the app running, docker compose stop db and call /health — it must return 503 while /health/live still returns 200.

Verify it yourself

Run these in order with the app running and Postgres up. Every one is pass or fail on its own — no judgement calls.

$ grep -rn "os.getenv" app/
                                  # empty output = all config goes through Settings

$ curl -s -o /dev/null -w '%{http_code}\n' localhost:8000/health
200                               # database reachable

$ curl -s -o /dev/null -w '%{http_code}\n' localhost:8000/health/live
200

$ curl -s -D - -o /dev/null localhost:8000/health | grep -i x-request-id
x-request-id: 7f3a1c92-5b0e-4d21-9c47-2a6f1b83e0d5   # a fresh uuid every call

$ tail -1 logs/app.log
{"ts": "2026-03-11T09:14:22.481+00:00", "level": "INFO", "logger": "app.request",
"msg": "request", "request_id": "7f3a1c92-5b0e-4d21-9c47-2a6f1b83e0d5",
"method": "GET", "path": "/health", "route": "/health", "status": 200,
"duration_ms": 4.13}
                                  # ONE line in your file - wrapped here to fit.
                                  # All ten fields must be present.

$ grep 7f3a1c92 logs/app.log | wc -l
       1                          # the id from the header is in the log. Same id.

# --- deliberate break 1: the database goes away -------------------------
$ docker compose stop db
$ curl -s -o /dev/null -w '%{http_code}\n' localhost:8000/health
503                               # tells the truth. {"ok": true} would say 200.

$ curl -s -o /dev/null -w '%{http_code}\n' localhost:8000/health/live
200                               # the process is fine - do NOT restart it

$ tail -2 logs/app.log | grep -o '"dependency": "postgres"'
"dependency": "postgres"          # the failure was logged, with a named field

$ docker compose start db         # put it back

# --- deliberate break 2: missing required config ------------------------
$ cp .env .env.bak
$ grep -v '^DATABASE_URL' .env.bak > .env
$ python -c "from app.config import get_settings; get_settings()"
CONFIG ERROR - the app cannot start:
  database_url: Field required
  See .env.example for every variable this app needs.

$ echo $?
1                                 # non-zero exit. A supervisor sees a failed start.

$ mv .env.bak .env                # restore, and confirm it boots again

# --- the payoff: which endpoint is slowest ------------------------------
$ grep '"logger": "app.request"' logs/app.log \
    | jq -r '[.duration_ms, .status, .method, .route] | @tsv' \
    | sort -rn | head -5
412.3	200	GET	/places          # your numbers will differ; the shape must not
88.1	200	GET	/lists/{list_id}
12.7	201	POST	/places
4.13	200	GET	/health
If /health returned 200 with the database stopped, you have not built a health check. The usual cause is a bare except that swallows the error, or checking a variable instead of running the query. Re-read the failure: the whole value of this endpoint is that it is willing to say no.

Prove it

Write your answers in notes/module-10.md before opening any of these. Question 1 requires you to actually run the pipeline — a guess does not count, and finding out you guessed wrong is the point of the exercise.

1. Which of your endpoints is slowest, and how do you know?

Show answer

The answer must be a route name and a number you obtained by aggregating duration_ms from your own log by route. Two things usually surprise people. First, the slowest endpoint is rarely the one you assumed — a list endpoint with an unnoticed N+1 from Module 06 routinely beats the "complicated" one. Second, the mean is a poor summary: a route at 40ms average can contain requests at 4 seconds, and those are the ones users report. Sort individual requests descending as well as averaging, and weight by call count — a slow endpoint nobody calls is not your problem yet.

2. Why is a health check that returns {"ok": true} unconditionally worse than having no health check at all?

Show answer

Because it is a confident lie, and things downstream act on it. A load balancer that gets 200 from a process whose database is gone keeps sending users to it — and worse, it may drain a healthy instance to make room, since by its measure both are equally fine. With no health check the platform knows it is uninformed and falls back to cruder signals like the process exiting. The unconditional endpoint replaces uncertainty with false certainty, which is the one thing that makes automated systems do actively harmful things. A health check's value comes entirely from its willingness to fail.

3. What is the difference between a liveness probe and a readiness probe, and what specifically goes wrong when you use one endpoint for both?

Show answer

Liveness asks "is this process wedged, should it be restarted?" and checks nothing but itself. Readiness asks "should traffic arrive right now?" and checks the dependencies needed to serve. Use a dependency-checking endpoint for liveness and a brief database outage becomes a restart loop: the probe fails, the platform kills the container, the replacement also cannot reach the database, it is killed too, across every instance. You have converted a ninety-second blip into a long outage, thrown away warm pools and in-flight work, and destroyed your logs, since each process dies before writing anything useful. Correct behaviour is that readiness fails, traffic stops, processes wait, and recovery is automatic.

4. Why should an application refuse to start when a required environment variable is missing, rather than starting and using a sensible default?

Show answer

Because of when and to whom the failure appears. Refusing to start fails at deploy time, in front of the engineer deploying, with a message naming the variable — and a non-zero exit means the rollout stops and the previous version keeps serving. Starting with a default defers the failure to the first request that needs it, at an unpredictable hour, as a 500 with a traceback that names NoneType rather than the missing config. For secrets it is worse than inconvenient: a default JWT_SECRET means tokens get signed with a value that is public in your repository, so the app appears to work perfectly while anyone can forge a token. A loud crash at the boundary is cheap; a quiet wrong value is not.

5. Why does structured JSON beat a well-written human-readable sentence in a log?

Show answer

Because logs are read by machines far more often than by people. A sentence forces every consumer to write a regular expression against wording that changes the moment someone edits the string — and it will change, because the same code path prints "412ms" and "1.2s". JSON gives named, typed fields, so filtering, grouping, and thresholds are queries rather than parsing, and adding a field breaks nothing. The objection is real: JSON is unpleasant to read raw. The answer is not prose, it is a tool — jq in development, a pretty console renderer if you want one locally, JSON everywhere the log is actually stored. Optimise for the reader who cannot improvise.

6. You add log.exception("failed", extra={"request": dict(request.headers)}) to your error handler. What have you just done?

Show answer

Leaked every credential the API has ever received. The headers dict contains Authorization: Bearer <jwt> for every authenticated request from Module 07, plus cookies and any API keys. Those lines are written in plain text, shipped to a log system, indexed for search, retained for months, and readable by anyone with log access — support staff, contractors, whoever inherits the account. Treat it as a leak: those tokens must be considered compromised and the signing key rotated, which invalidates every token in circulation. The general rule is that you log fields you chose deliberately by name, never a whole object, because objects grow new sensitive attributes without anyone revisiting the log line. If you must log headers, allow-list the two or three you need.