Logging Predictions and Service Health

Context

A service you can watch writes one JSON object per line for every request it answers, naming the method, the path, the status and the milliseconds it took, keeps running counts that /health reports beside the model version it serves, and stores each prediction's model version and latency next to the listing and the price. Underneath, a connection pool (a small set of open database connections the service borrows from and gives back, replacing any that broke) keeps that storing alive when the database restarts.

You read these records the morning a client says prices have turned slow, and after a deploy, to compare two model versions by how many listings each priced, how fast and at what average price. Docker reads /health every five seconds to decide whether the container is healthy, and the next lesson measures drift on the listings the table holds.

Lesson 6.3.3's stack logs only uvicorn's access line, a sentence written for a person, with no latency and no model version in it. Its table cannot say which model priced a row. And its one database connection, opened at startup, dies with the first database restart: from then on every /predict answers 500 while /health says ok and Docker reports the container healthy.

Goal

• Write logs.py, a JSON formatter on Python's logging module, and predict what it prints for an event with fields, without fields, and with a key that clashes with the log record.
• Build a FastAPI middleware that logs and counts every request, a 500 from an unhandled exception included, and show what a version without finally loses.
• Extend /health with the model version, the uptime and the request, 422 and 5xx counts, and account for every request it counts, Docker's own probes among them.
• Store the model version and the model's latency with every prediction, and compare versions in SQL by count, average and 95th-percentile latency and average price.
• Diagnose the 500s a database restart causes on one connection, fix them with a ConnectionPool that checks each connection before lending it, and keep the test suite's predictions out of the real table.

Prerequisites

None of this is required, the lesson stands on its own. Both are here for anyone who wants the logging model or the pool explained first.

• YouTube - "Modern Python logging" by mCoding. Twenty-one minutes on loggers, handlers and formatters, configuring them, writing JSON logs, and passing extra context with the extra parameter.
• psycopg documentation - "Connection pools", Connection quality. Why a pool does not notice a connection that broke while it sat idle, and the check callback, ConnectionPool.check_connection among them, that tests each connection before a client gets it.

Table of Contents

• Structured Logs, One JSON Object per Line
• A Middleware That Times and Counts Every Request
• A Health Report Beyond "ok"
• Model Version and Latency in Every Stored Prediction
• A Connection Pool That Survives a Database Restart

Theory

Everything runs in ~/dev/listings-service at Lesson 6.3.4's commit, with (bootcamp) deactivated as Module 6's setup page says. The compose stack of Lesson 6.3.3 is built from it, its pgdata volume holding the predictions table with the three rows that lesson logged, and model/ holds the exported champion, version 3. The lesson writes src/listings/logs.py, changes src/listings/app.py, src/listings/db.py, Dockerfile, tests/test_app.py and tests/test_db.py, adds psycopg's pool to pyproject.toml and uv.lock, and commits the eight at the end. Probes live in Lesson 6.1.3's ~/dev/listings-probes, run as uv run python ../listings-probes/<name>.py. A server runs in Terminal 1 and every curl in Terminal 2, both in the project folder, and a PID, a timestamp, a latency and an uptime differ on every run.

The first three subtitles run the service on your machine, so stop the stack before the first of them. docker compose down removes the containers and keeps the volume, so the table and its rows survive:

docker compose down

Structured Logs, One JSON Object per Line

What. A structured log line is one JSON object on one line, whose keys a program reads without parsing a sentence: time, level, event, and the fields that event carries. logs.py builds it on Python's standard logging module from three parts: a logger, the named object code calls .info() or .warning() on, a handler, which decides where the line goes, here the terminal's standard error, and a formatter, which turns one log record into text, here with json.dumps. Why. Uvicorn's access line, "POST /predict HTTP/1.1" 200 OK, was written to be read by a person. Counting the 500s in a day of them, or averaging a latency it never printed, means writing a parser for a sentence. A JSON line comes back as a dictionary from json.loads, in your own script or in any log system a team runs. When. For every event a service reports that someone will later count, filter or average.

Nothing is installed, logging and json ship with Python. Save src/listings/logs.py:

"""One JSON object per log line, so a machine can read the service's logs."""

import json
import logging


class JsonFormatter(logging.Formatter):
    def format(self, record):
        entry = {
            "time": self.formatTime(record, "%Y-%m-%dT%H:%M:%S"),
            "level": record.levelname,
            "event": record.getMessage(),
        }
        entry.update(getattr(record, "fields", {}))
        return json.dumps(entry)


def get_logger(name="listings"):
    logger = logging.getLogger(name)
    if not logger.handlers:
        handler = logging.StreamHandler()
        handler.setFormatter(JsonFormatter())
        logger.addHandler(handler)
        logger.setLevel(logging.INFO)
        logger.propagate = False
    return logger

A log record is the object logging builds for each call, and format receives it and returns the line. formatTime writes the record's time in the local time zone, levelname is INFO or WARNING, and getMessage() is the text passed to the call, used as the event's name. The event's fields arrive as one attribute, record.fields, because logging copies every key of a call's extra= dictionary onto the record, and getattr(record, "fields", {}) gives an empty dictionary for a call that passed none. logging.getLogger(name) returns the same logger for the same name everywhere in the process, so get_logger attaches its handler only once. setLevel(logging.INFO) lets info through, where an unconfigured logger passes only warnings and worse. propagate = False keeps the record from also travelling up to the root logger, the parent of every named logger, whose handler, if anything configured one, would print it a second time.

A probe, ~/dev/listings-probes/try_logs.py:

from listings.logs import get_logger

logger = get_logger()
logger.info("startup", extra={"fields": {"model_version": "3"}})
logger.warning("slow request", extra={"fields": {"path": "/predict", "latency_ms": 812.4}})
logger.info("no fields")
print(get_logger() is logger, len(logger.handlers))

uv run python ../listings-probes/try_logs.py

{"time": "2026-11-03T15:20:30", "level": "INFO", "event": "startup", "model_version": "3"}
{"time": "2026-11-03T15:20:30", "level": "WARNING", "event": "slow request", "path": "/predict", "latency_ms": 812.4}
{"time": "2026-11-03T15:20:30", "level": "INFO", "event": "no fields"}
True 1

Each call is one line, its fields after the three fixed keys, and the second get_logger() returned the same logger with one handler. The log lines go to standard error and print's line to standard output, so the same command with 2>/dev/null, which throws standard error away, prints True 1 alone.

Three variants, each run, show what the parts of logs.py prevent. Without the if not logger.handlers guard, two calls to get_logger() attached two handlers, and one startup event printed as two identical lines. With propagate left at True and logging.basicConfig() called first, the way a library or a notebook often configures the root logger, the event printed once as JSON and once more as INFO:listings:startup. And a field passed straight in extra fails two ways: extra={"status": 200} printed the line with no status in it, because the formatter copies only record.fields, and extra={"msg": "hello"} raised before anything printed:

KeyError: "Attempt to overwrite 'msg' in LogRecord"

msg is one of the attributes every log record already has, args and levelname among the others, and logging refuses an extra key that would replace one. The single name fields clears every built-in attribute and gives the formatter exactly the keys to write.

DON'T:

• DON'T call logging.getLogger(...).addHandler(...) wherever a logger is needed. Each call adds one more handler to the same logger, and the variant without the guard printed one event twice.
• DON'T pass event fields as bare extra keys. status vanished from the line without a word, and msg raised KeyError.
• DON'T leave propagate on beside a configured root logger. The same event came out twice, once as JSON and once as INFO:listings:startup.

A Middleware That Times and Counts Every Request

What. A middleware is a function FastAPI runs around every request: it receives the request and call_next, a function that passes the request on to the matching route and returns its response, so code before call_next runs before the route and code after it runs once the response exists. log_request starts a timer, awaits the response, and in a finally block computes the latency, adds one to a count for the status, and logs a request event with the method, the path, the status and the latency. Why. A route sees only its own requests and only when it runs. A middleware sees every request, a 404 for a path no route serves, a 422 that validation refused before the route body ran, and a 500 from a route that raised, so it is the one place where a count and a latency can be complete. When. For anything every request must do the same way, logging, timing and counting among them.

src/listings/app.py gets its final form in one edit. The /health route and the version lines belong to the next subtitle, and the timing and the two new arguments in predict to the fourth.

"""The price service: one listing in, one price out, every price logged."""

import os
import time
from collections import Counter
from contextlib import asynccontextmanager
from pathlib import Path

import mlflow
from fastapi import FastAPI, Request

from listings import db
from listings.data import to_frame
from listings.logs import get_logger
from listings.schema import Listing, Quote

DEFAULT_MODEL_URI = "model"
logger = get_logger()


def read_version(model_dir):
    meta = Path(model_dir, "registered_model_meta")
    if not meta.exists():
        return "unregistered"
    fields = dict(line.split(": ", 1) for line in meta.read_text().splitlines())
    return fields["model_version"]


@asynccontextmanager
async def lifespan(app):
    uri = os.environ.get("MODEL_URI", DEFAULT_MODEL_URI)
    app.state.model = mlflow.pyfunc.load_model(uri)
    app.state.version = read_version(uri)
    app.state.counts = Counter()
    app.state.started = time.time()
    url = os.environ.get("DATABASE_URL")
    app.state.db = db.connect(url) if url else None
    logger.info("startup", extra={"fields": {"model_version": app.state.version}})
    yield
    if app.state.db is not None:
        app.state.db.close()


app = FastAPI(title="listings-service", lifespan=lifespan)


@app.middleware("http")
async def log_request(request, call_next):
    start = time.perf_counter()
    status = 500
    try:
        response = await call_next(request)
        status = response.status_code
        return response
    finally:
        latency_ms = round((time.perf_counter() - start) * 1000, 2)
        request.app.state.counts[status] += 1
        logger.info("request", extra={"fields": {
            "method": request.method, "path": request.url.path,
            "status": status, "latency_ms": latency_ms,
        }})


@app.get("/health")
def health(request: Request):
    state = request.app.state
    return {
        "status": "ok",
        "model_version": state.version,
        "uptime_s": round(time.time() - state.started),
        "requests": state.counts.total(),
        "rejected": state.counts[422],
        "errors": sum(n for code, n in state.counts.items() if code >= 500),
    }


@app.post("/predict")
def predict(listing: Listing, request: Request) -> Quote:
    state = request.app.state
    row = listing.model_dump()
    start = time.perf_counter()
    price = round(state.model.predict(to_frame([row]))[0])
    latency_ms = round((time.perf_counter() - start) * 1000, 2)
    if state.db is not None:
        db.log_prediction(state.db, row, price, state.version, latency_ms)
    return Quote(price=price)

@app.middleware("http") registers log_request for every HTTP request, and it is async def because it awaits call_next. time.perf_counter() is the clock Lesson 6.2.4's Assignment timed with. counts is a Counter, Lesson 6.2.4's Lab tally, created in the lifespan so every start of the service counts from zero.

The line that needs more than a comment is status = 500 before the try. When the route raises an exception nobody catches, call_next raises it again here, status = response.status_code never runs, and the finally block still runs on the way out with the 500 in place. The exception then carries on to Starlette, Lesson 6.2.3's toolkit under FastAPI, which answers the client with 500 while uvicorn prints the traceback. A variant without the try, logging after response = await call_next(request), served a test route that raised RuntimeError: the client got its 500, and the log had no line for it and the count no entry.

Start the service in Terminal 1, the way Lesson 6.2.4 did:

uv run uvicorn listings.app:app

Once Uvicorn running on has printed, set the reference listing in Terminal 2 and send it, then a request missing most of its fields:

LISTING='{"area_sqm": 85.0, "year_built": 1998, "distance_km": 3.0, "rooms": 3, "bathrooms": 1, "neighborhood": "Riverside", "property_type": "apartment", "energy_rating": "C", "condition": "good"}'
curl -s -X POST http://127.0.0.1:8000/predict -H "Content-Type: application/json" -d "$LISTING"; echo
curl -s -o /dev/null -w '%{http_code}\n' -X POST http://127.0.0.1:8000/predict -H "Content-Type: application/json" -d '{"rooms": 0}'

{"price":384235}
422

-o /dev/null throws the body away and -w '%{http_code}\n' prints only the status. Terminal 1, from the start:

INFO:     Started server process [63534]
INFO:     Waiting for application startup.
{"time": "2026-11-03T15:21:50", "level": "INFO", "event": "startup", "model_version": "3"}
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
{"time": "2026-11-03T15:21:50", "level": "INFO", "event": "request", "method": "POST", "path": "/predict", "status": 200, "latency_ms": 41.56}
INFO:     127.0.0.1:52890 - "POST /predict HTTP/1.1" 200 OK
{"time": "2026-11-03T15:21:50", "level": "INFO", "event": "request", "method": "POST", "path": "/predict", "status": 422, "latency_ms": 0.75}
INFO:     127.0.0.1:52904 - "POST /predict HTTP/1.1" 422 Unprocessable Entity

The startup event names the version loaded. Every request prints twice, as JSON from the middleware and as uvicorn's access line, which comes second because uvicorn writes it as the response is sent, after the middleware's finally has run. The access line adds only the client's address, so uvicorn's --no-access-log turns it off. The 422 took about a millisecond, because validation refused it before predict ran. The priced listing took 41.56 milliseconds, and the first priced request after a start is the slowest: in a run of six, the first took 42.3 and the five after it 11 to 15. The container gets the same flag. The last line of Dockerfile becomes:

CMD ["uvicorn", "listings.app:app", "--host", "0.0.0.0", "--port", "8000", "--no-access-log"]

Stop the service with Ctrl+C and start it again with the flag, and leave it running for the next subtitle:

uv run uvicorn listings.app:app --no-access-log

DON'T:

• DON'T log after call_next without try and finally. The variant served a 500 that never reached the log or the count.
• DON'T keep uvicorn's access log beside the JSON one. Every request printed twice, and a script counting lines would count each one double.
• DON'T read the first request's latency as the service's speed. It took 42.3 milliseconds where the five after it took 11 to 15.

A Health Report Beyond "ok"

What. /health now answers with six fields: status, always ok while the process answers, model_version, read once at startup from the model folder, uptime_s, whole seconds since the lifespan ran, requests, every request the middleware has counted, rejected, the 422s, and errors, every status of 500 or more. Why. A bare ok proves only that the process answers HTTP. The version says which model a complaint is about, the uptime whether the service restarted, and the counts whether clients are refused or failed, all with one curl. When. Every time someone asks what is running and how it is doing, and every time Docker's healthcheck, Lesson 6.3.3's probe in compose.yaml, calls it.

read_version reads the file registered_model_meta that Lesson 6.3.3's mlflow artifacts download wrote into model/, two lines in the form model_version: 3, and line.split(": ", 1) cuts each line once at the first colon and space, so dict(...) maps each name to its value. A model folder without the file, such as the one the test fixture saves with mlflow.sklearn.save_model, reports unregistered instead of failing. Counter.total() is the sum of every count, and state.counts[422] reads a status that never occurred as 0. In Terminal 2, send the two requests to the restarted service and read /health, then send a path no route serves, a method the route does not accept, and read it again:

curl -s -X POST http://127.0.0.1:8000/predict -H "Content-Type: application/json" -d "$LISTING"; echo
curl -s -o /dev/null -w '%{http_code}\n' -X POST http://127.0.0.1:8000/predict -H "Content-Type: application/json" -d '{"rooms": 0}'
curl -s http://127.0.0.1:8000/health; echo
curl -s http://127.0.0.1:8000/nope; echo
curl -s -X DELETE http://127.0.0.1:8000/predict; echo
curl -s http://127.0.0.1:8000/health; echo

{"price":384235}
422
{"status":"ok","model_version":"3","uptime_s":4,"requests":2,"rejected":1,"errors":0}
{"detail":"Not Found"}
{"detail":"Method Not Allowed"}
{"status":"ok","model_version":"3","uptime_s":4,"requests":5,"rejected":1,"errors":0}

Terminal 1 now prints one line per request, the first two:

{"time": "2026-11-03T15:22:03", "level": "INFO", "event": "request", "method": "POST", "path": "/predict", "status": 200, "latency_ms": 19.81}
{"time": "2026-11-03T15:22:03", "level": "INFO", "event": "request", "method": "POST", "path": "/predict", "status": 422, "latency_ms": 0.56}

uptime_s is 4 because these requests came four seconds after the start. The first /health reports two requests, not three, because the middleware counts a request in its finally, after the route has already built the reply: a health report never includes itself. The second reports five, the first /health among them, and the 404 and the 405 are counted in requests and in neither rejected nor errors, because neither is a 422 nor a server failure. Stop the service with Ctrl+C.

The test of /health in tests/test_app.py asserted the whole old body, {"status": "ok"}, and fails on the new one. Replace it with these two tests:

def test_health(client):
    response = client.get("/health")
    assert response.status_code == 200
    assert response.json()["status"] == "ok"
    assert response.json()["model_version"] == "unregistered"


def test_health_counts_requests(client):
    client.post("/predict", json=LISTING)
    client.post("/predict", json=LISTING | {"rooms": 0})
    health = client.get("/health").json()
    assert health["requests"] == 2
    assert health["rejected"] == 1
    assert health["errors"] == 0

The first asserts only the fields that do not depend on time, unregistered being the fixture's folder. The second pins the counting rule just observed, and starts from zero because each with TestClient(app) runs the lifespan, which creates a fresh Counter.

uv run pytest

The per-file lines and the last line:

tests/test_app.py .........                                              [ 32%]
tests/test_data.py ....                                                  [ 46%]
tests/test_db.py s                                                       [ 50%]
tests/test_features.py .....                                             [ 67%]
tests/test_model.py .........                                            [100%]
================== 27 passed, 1 skipped, 2 warnings in 1.96s ===================

The suite holds 28 tests, one more than Lesson 6.3.4's, and the one skipped is Lesson 6.3.2's database test, which runs only when DATABASE_URL is set. The warnings are Lesson 6.2.4's two.

DON'T:

• DON'T assert the whole /health body in a test. uptime_s changes every second, and the old == {"status": "ok"} failed the moment a field was added.
• DON'T read requests as the number of requests sent before it, the health call included. It counts only finished requests, so it never includes the call that reads it.
• DON'T read status: ok as "the service is working". It is written as a constant, and it stays ok while every prediction fails, as the last subtitle shows.

Model Version and Latency in Every Stored Prediction

What. The predictions table gains two columns, model_version, the text /health reports, and latency_ms, the time predict spent building the frame and running the model, and log_prediction writes both with each row. ALTER TABLE ... ADD COLUMN IF NOT EXISTS adds a column to a table that already exists, and does nothing when the column is there. Why. A row that says what was asked and answered but not which model answered cannot be compared across a deploy, and the drift and retraining of the next lesson need exactly that comparison. IF NOT EXISTS lets the same startup code run against the table Section 6.3 created, a new empty database, and a database this code already migrated. When. Whenever a service stores its outputs, and every time a stored table needs a column it did not have.

src/listings/db.py keeps its one connection for now and becomes:

"""Every prediction the service returns, written to PostgreSQL."""

import psycopg
from psycopg.types.json import Jsonb

SCHEMA = [
    """
    CREATE TABLE IF NOT EXISTS predictions (
        id bigint GENERATED ALWAYS AS IDENTITY PRIMARY KEY,
        created_at timestamptz NOT NULL DEFAULT now(),
        listing jsonb NOT NULL,
        price double precision NOT NULL
    )
    """,
    "ALTER TABLE predictions ADD COLUMN IF NOT EXISTS model_version text",
    "ALTER TABLE predictions ADD COLUMN IF NOT EXISTS latency_ms double precision",
]


def connect(url):
    conn = psycopg.connect(url, autocommit=True)
    for statement in SCHEMA:
        conn.execute(statement)
    return conn


def log_prediction(conn, listing, price, model_version=None, latency_ms=None):
    row = conn.execute(
        "INSERT INTO predictions (listing, price, model_version, latency_ms)"
        " VALUES (%s, %s, %s, %s) RETURNING id",
        (Jsonb(listing), price, model_version, latency_ms),
    ).fetchone()
    return row[0]

SCHEMA becomes a list run in order, one execute per statement: Lesson 6.3.2's CREATE TABLE, unchanged, then one ALTER per new column. An added column is NULL in every row already stored, so the rows from before this lesson stay valid, and the two new parameters default to None, so Lesson 6.3.2's test still calls log_prediction(conn, BLANK, 434348). In predict, the timer covers to_frame and the model alone, where the middleware's latency is the whole request, validation and the database write included.

Build and start the stack, --wait holding the command until both containers are healthy, then read the table's columns with psql, the PostgreSQL client inside the db container:

docker compose up -d --build --wait
docker compose exec db psql -U listings -d listings -c '\d predictions'

The last lines of the build and the table:

 Container listings-service-db-1 Healthy 
 Container listings-service-api-1 Healthy 
                                   Table "public.predictions"
    Column     |           Type           | Collation | Nullable |           Default            
---------------+--------------------------+-----------+----------+------------------------------
 id            | bigint                   |           | not null | generated always as identity
 created_at    | timestamp with time zone |           | not null | now()
 listing       | jsonb                    |           | not null | 
 price         | double precision         |           | not null | 
 model_version | text                     |           |          | 
 latency_ms    | double precision         |           |          | 
Indexes:
    "predictions_pkey" PRIMARY KEY, btree (id)

The two ALTER statements ran at the API's startup. Send the third subtitle's first three commands again, the two requests and /health, then read the API's last log lines:

docker compose logs api | tail -5

The three replies and the log:

{"price":384235}
422
{"status":"ok","model_version":"3","uptime_s":9,"requests":4,"rejected":1,"errors":0}
api-1  | {"time": "2026-11-03T14:23:03", "level": "INFO", "event": "request", "method": "GET", "path": "/health", "status": 200, "latency_ms": 1.44}
api-1  | {"time": "2026-11-03T14:23:09", "level": "INFO", "event": "request", "method": "GET", "path": "/health", "status": 200, "latency_ms": 0.68}
api-1  | {"time": "2026-11-03T14:23:10", "level": "INFO", "event": "request", "method": "POST", "path": "/predict", "status": 200, "latency_ms": 26.84}
api-1  | {"time": "2026-11-03T14:23:10", "level": "INFO", "event": "request", "method": "POST", "path": "/predict", "status": 422, "latency_ms": 0.67}
api-1  | {"time": "2026-11-03T14:23:10", "level": "INFO", "event": "request", "method": "GET", "path": "/health", "status": 200, "latency_ms": 0.51}

requests is 4 after two requests of yours. The /health lines at 14:23:03 and 14:23:09 are Docker's: the API's healthcheck in compose.yaml calls /health every five seconds, and the middleware counts those calls like any other, so your count is higher by about one for every five seconds the container has run. A figure from /health is "requests the process answered", never "requests clients sent". The log's clock reads 14:23 where the host's said 15:23, because formatTime writes local time and the container's local time is UTC.

Send twenty more listings:

for i in $(seq 1 20); do curl -s -o /dev/null -X POST http://127.0.0.1:8000/predict -H "Content-Type: application/json" -d "$LISTING"; done

Now the question the columns exist for, one row per model version. Open psql with docker compose exec db psql -U listings -d listings, and at its listings=# prompt run:

SELECT model_version,
       count(*) AS n,
       round(avg(latency_ms)::numeric, 2) AS avg_ms,
       round(percentile_cont(0.95) WITHIN GROUP (ORDER BY latency_ms)::numeric, 2) AS p95_ms,
       round(avg(price)) AS avg_price
FROM predictions
GROUP BY model_version
ORDER BY model_version;

 model_version | n  | avg_ms | p95_ms | avg_price 
---------------+----+--------+--------+-----------
 3             | 21 |   6.94 |   8.28 |    384235
               |  3 |        |        |    417644
(2 rows)

GROUP BY, count(*) and avg are Lesson 2.1.3's. percentile_cont(0.95) WITHIN GROUP (ORDER BY latency_ms) is the 95th percentile, the value 95 percent of the group's latencies sit under, interpolated between two rows where needed, the SQL form of Lesson 2.2.5's np.percentile: an average hides a few slow requests among many fast ones, and the 95th percentile shows them. ::numeric converts to PostgreSQL's exact decimal type, because round with a number of places exists only for it: round(avg(latency_ms), 2) fails with function round(double precision, integer) does not exist. GROUP BY collects every NULL version into one group, the last line, the rows stored before this lesson: here the three Lesson 6.3.3 logged, the test run's 384235 and 434348 and Lab Exercise 2's 434348. Leave psql with \q.

Now run the suite with Lesson 6.3.2's database test included, against the stack's PostgreSQL on its published port, as Lesson 6.3.3 did:

DATABASE_URL=postgresql://listings:listings@localhost:5432/listings uv run pytest

======================== 28 passed, 2 warnings in 1.67s ========================

Every test passed, and the app tests wrote into the real table through the client fixture's lifespan, as Lesson 6.3.2 found. The new column names those rows. The same query, run again:

 model_version | n  | avg_ms | p95_ms | avg_price 
---------------+----+--------+--------+-----------
 3             | 21 |   6.94 |   8.28 |    384235
 unregistered  |  3 |   7.07 |   7.10 |    400939
               |  3 |        |        |    417644
(3 rows)

Three rows of version unregistered arrived, one from each app test that reaches predict, the new test_health_counts_requests among them, averaging 400939. Read by version, the table says plainly that something other than the service wrote to it, rows the next lesson's drift measurement would have counted as traffic. The fixture now unsets the variable for every app test, one line under setenv:

@pytest.fixture
def client(model_dir, monkeypatch):
    monkeypatch.setenv("MODEL_URI", str(model_dir))
    monkeypatch.delenv("DATABASE_URL", raising=False)
    with TestClient(app) as client:
        yield client

monkeypatch.delenv removes the variable for the one test and restores it afterwards, and raising=False keeps it quiet when the variable was never set. Run the suite with DATABASE_URL again: 28 pass, the database test still runs, because it reads the variable at import time, and the unregistered count stays at 3. Delete those three:

docker compose exec db psql -U listings -d listings -c "DELETE FROM predictions WHERE model_version = 'unregistered'"

DELETE 3

DON'T:

• DON'T add a column by editing the CREATE TABLE. CREATE TABLE IF NOT EXISTS skips a table that exists, so the volume's table would never get the column, and every insert naming it would fail.
• DON'T compare versions on the table's latency_ms alone. It is the model's time, and the request the client waited for is the middleware's.
• DON'T keep the app tests out of the table by unsetting DATABASE_URL for the whole run. The database test then skips, where the fixture's delenv kept the three app tests out and test_db.py still ran and passed.

A Connection Pool That Survives a Database Restart

What. A connection pool opens database connections, lends one to each piece of code that asks, takes it back afterwards, and replaces any it finds broken. psycopg's ConnectionPool does this, and check=ConnectionPool.check_connection makes it test each connection with an empty query before lending it, so a connection the server closed is thrown away and a fresh one handed out instead. Why. One connection opened at startup lives exactly as long as the database process it talks to. Restart PostgreSQL, for an upgrade, a setting or a reboot, and that connection is dead for good while the service around it keeps answering. When. In every service that talks to a database for longer than one script run.

The pool is a separate package, psycopg-pool, that psycopg installs as its pool extra, the same way Lesson 6.3.2 installed psycopg with its binary extra:

uv add "psycopg[binary,pool]==3.3.6"

Resolved 101 packages in 11.52s
   Building listings @ file:///home/goku/dev/listings-service
      Built listings @ file:///home/goku/dev/listings-service
Prepared 2 packages in 332ms
Uninstalled 1 package in 0.28ms
Installed 2 packages in 0.81ms
 ~ listings==0.1.0 (from file:///home/goku/dev/listings-service)
 + psycopg-pool==3.3.3

psycopg stays at 3.3.6, and psycopg-pool 3.3.3 is the one new package. The stack still runs the image built in the last subtitle, one connection and all. Break it the way a routine database restart does:

docker compose restart db

 Container listings-service-db-1 Restarting 
 Container listings-service-db-1 Started 

Then the same three commands, the two requests and /health, twice:

Internal Server Error
422
{"status":"ok","model_version":"3","uptime_s":55,"requests":36,"rejected":2,"errors":1}
Internal Server Error
422
{"status":"ok","model_version":"3","uptime_s":55,"requests":39,"rejected":3,"errors":2}

And what Docker thinks of it:

docker compose ps --format '{{.Name}} {{.Status}}'

listings-service-api-1 Up About a minute (healthy)
listings-service-db-1 Up 8 seconds (healthy)

Every priced listing fails with a 500, every refused one still gets its 422, /health says ok, and Docker reports both containers healthy, because its probe asks /health, which never touches the database. The one signal that moved is errors. docker compose logs api shows each failure as the middleware's line followed by uvicorn's traceback, the first one's two deepest project frames and its last line being:

api-1  | {"time": "2026-11-03T14:23:56", "level": "INFO", "event": "request", "method": "POST", "path": "/predict", "status": 500, "latency_ms": 14.34}
api-1  | ERROR:    Exception in ASGI application
api-1  |   File "/app/src/listings/app.py", line 85, in predict
api-1  |     db.log_prediction(state.db, row, price, state.version, latency_ms)
api-1  |   File "/app/src/listings/db.py", line 28, in log_prediction
api-1  |     row = conn.execute(
api-1  | psycopg.errors.AdminShutdown: terminating connection due to administrator command

The second ends at the same lines with psycopg.OperationalError: the connection is closed. The paths are the container's /app. When PostgreSQL stops, it ends every open session with terminating connection due to administrator command, and psycopg raises it as AdminShutdown at the connection's next use, the first INSERT. psycopg then marks the connection closed, every later use fails at once, and nothing opens another, because db.connect ran once, in the lifespan. The model had priced each listing before the insert raised, and the client still got a 500 and no price, and the table no row.

The fix replaces the connection with a pool in src/listings/db.py:

"""Every prediction the service returns, written to PostgreSQL."""

from psycopg.types.json import Jsonb
from psycopg_pool import ConnectionPool

SCHEMA = [
    """
    CREATE TABLE IF NOT EXISTS predictions (
        id bigint GENERATED ALWAYS AS IDENTITY PRIMARY KEY,
        created_at timestamptz NOT NULL DEFAULT now(),
        listing jsonb NOT NULL,
        price double precision NOT NULL
    )
    """,
    "ALTER TABLE predictions ADD COLUMN IF NOT EXISTS model_version text",
    "ALTER TABLE predictions ADD COLUMN IF NOT EXISTS latency_ms double precision",
]


def connect(url):
    pool = ConnectionPool(
        url,
        min_size=1,
        max_size=4,
        kwargs={"autocommit": True},
        check=ConnectionPool.check_connection,
        open=True,
    )
    with pool.connection() as conn:
        for statement in SCHEMA:
            conn.execute(statement)
    return pool


def log_prediction(pool, listing, price, model_version=None, latency_ms=None):
    with pool.connection() as conn:
        row = conn.execute(
            "INSERT INTO predictions (listing, price, model_version, latency_ms)"
            " VALUES (%s, %s, %s, %s) RETURNING id",
            (Jsonb(listing), price, model_version, latency_ms),
        ).fetchone()
    return row[0]

min_size=1 keeps one connection open while the service is idle, and max_size=4 lets the pool grow to four when requests overlap, since FastAPI runs a plain def route like predict in a pool of threads. kwargs goes to every psycopg.connect the pool makes, so each connection is in autocommit as before, and open=True opens the pool as it is built, so the SCHEMA block can borrow at once. with pool.connection() as conn: borrows a connection for the block and returns it when the block ends, whatever happens inside. app.py needs no change: it passes state.db through and calls close() at shutdown, which a pool has too.

check is what makes the restart survivable. Before lending a connection, the pool runs check_connection, whose source executes an empty query, one round trip per borrow. When that raises, the pool discards the connection and lends a newly opened one, and the first request after a restart pays for it, about a second here. Without check, the pool lends the dead connection to the next request, which fails before the pool notices.

tests/test_db.py is rewritten for the pool, and now checks the two new columns too:

import os

import pytest

from listings import db

URL = os.environ.get("DATABASE_URL")
BLANK = {
    "area_sqm": None, "year_built": None, "distance_km": 3.0, "rooms": 3,
    "bathrooms": 1, "neighborhood": "Riverside", "property_type": "apartment",
    "energy_rating": None, "condition": "good",
}


@pytest.mark.skipif(URL is None, reason="DATABASE_URL is not set")
def test_prediction_is_stored():
    pool = db.connect(URL)
    row_id = db.log_prediction(pool, BLANK, 434348, "1", 12.5)
    with pool.connection() as conn:
        stored = conn.execute(
            "SELECT listing, price, model_version, latency_ms"
            " FROM predictions WHERE id = %s", (row_id,)
        ).fetchone()
        conn.execute("DELETE FROM predictions WHERE id = %s", (row_id,))
    pool.close()
    assert stored == (BLANK, 434348.0, "1", 12.5)

uv run pytest
DATABASE_URL=postgresql://listings:listings@localhost:5432/listings uv run pytest

The last line of each:

================== 27 passed, 1 skipped, 2 warnings in 1.63s ===================
======================== 28 passed, 2 warnings in 1.70s ========================

Rebuild the stack, which now installs psycopg-pool from the lock:

docker compose up -d --build --wait

Then the two requests and /health once:

{"price":384235}
422
{"status":"ok","model_version":"3","uptime_s":3,"requests":3,"rejected":1,"errors":0}

The same restart:

docker compose restart db

Then the same three commands twice:

{"price":384235}
422
{"status":"ok","model_version":"3","uptime_s":12,"requests":7,"rejected":2,"errors":0}
{"price":384235}
422
{"status":"ok","model_version":"3","uptime_s":12,"requests":10,"rejected":3,"errors":0}

Every listing is priced, errors stays at 0, and docker compose logs api | grep -c -E 'Exception|Error' prints 0. The cost is in the log: the first /predict after the restart took 951.0 milliseconds, the pool's one-second wait, and the next 11.69. Four restarts gave 951 to 1,095 milliseconds for the first request each time, while the table's latency_ms for that request read 8.1, the model's time, which never saw the wait. Commit the eight files:

git add Dockerfile pyproject.toml uv.lock src/listings/logs.py src/listings/app.py src/listings/db.py tests/test_app.py tests/test_db.py
git commit -m "feat: structured logs, a health report and a connection pool"

[main b514778] feat: structured logs, a health report and a connection pool
 8 files changed, 149 insertions(+), 35 deletions(-)
 create mode 100644 src/listings/logs.py

The hash is your commit's own and differs from this one.

DON'T:

• DON'T open one connection in the lifespan for a long-running service. One docker compose restart db turned every /predict into a 500, and nothing in the service could open a new connection.
• DON'T trust Docker's healthy as proof that predictions work. Both containers read healthy while every priced listing failed.
• DON'T create the pool without check. The pool then lends the dead connection, and the request that receives it fails.

Lab Exercises

Lab Exercise 1: A Report From the API's Own Log

Write ~/dev/listings-probes/log_report.py, which reads log lines from standard input, keeps every request event among the lines that parse as JSON, and prints one sorted line per method, path and status with the count and the mean and maximum latency, then the number of request lines and of lines that were not JSON. Recreate the API container so its log and its counts start together, docker compose up -d --force-recreate --wait api, send the twenty listings of the fourth subtitle, the two requests and /health, and /nope, then on one line read /health and pipe docker compose logs api --no-log-prefix into the script, the flag dropping the api-1 | prefix. Say in a comment where the lines that are not JSON come from, whose /health lines these are, and why the logged total differs from requests.

Lab Exercise 2: What check Buys

Write ~/dev/listings-probes/pool_check.py, run with DATABASE_URL set as in the fourth subtitle. It builds two pools, checked from db.connect and plain, a ConnectionPool with the same URL, sizes and kwargs and no check, and a function that writes three predictions of the blank listing through a pool with db.log_prediction, as version probe, returning for each write ok or the exception's class name with the milliseconds it took. Write three through each pool, restart the database with subprocess.run(["docker", "compose", "restart", "db"], capture_output=True), wait three seconds, and print each pool's three results. Delete the probe rows and close both pools. Say in a comment what each pool's first write shows and where the line between them comes from.

import json
import sys
from collections import defaultdict

latencies = defaultdict(list)
other = 0
for line in sys.stdin:
    try:
        entry = json.loads(line)
    except json.JSONDecodeError:
        other += 1
        continue
    if entry["event"] == "request":
        key = (entry["method"], entry["path"], entry["status"])
        latencies[key].append(entry["latency_ms"])

for (method, path, status), values in sorted(latencies.items()):
    mean = sum(values) / len(values)
    print(f"{method:5} {path:9} {status}  n={len(values):3}  mean={mean:6.2f} ms  max={max(values):6.2f} ms")
print("requests logged:", sum(len(v) for v in latencies.values()), "| other lines:", other)
# Not JSON: uvicorn's four startup lines. /health: 2 of mine, 3 of Docker's
# probes. 28 logged against 27 reported: the last /health was logged after
# it had counted, and every probe since the reply adds a line.

curl -s http://127.0.0.1:8000/health; echo; docker compose logs api --no-log-prefix | uv run python ../listings-probes/log_report.py

{"status":"ok","model_version":"3","uptime_s":13,"requests":27,"rejected":1,"errors":0}
GET   /health   200  n=  5  mean=  0.76 ms  max=  1.26 ms
GET   /nope     404  n=  1  mean=  0.23 ms  max=  0.23 ms
POST  /predict  200  n= 21  mean= 14.58 ms  max= 34.57 ms
POST  /predict  422  n=  1  mean=  0.75 ms  max=  0.75 ms
requests logged: 28 | other lines: 4

import os
import subprocess
import time

from psycopg_pool import ConnectionPool

from listings import db

URL = os.environ["DATABASE_URL"]
BLANK = {
    "area_sqm": None, "year_built": None, "distance_km": 3.0, "rooms": 3,
    "bathrooms": 1, "neighborhood": "Riverside", "property_type": "apartment",
    "energy_rating": None, "condition": "good",
}


def unchecked(url):
    return ConnectionPool(url, min_size=1, max_size=4,
                          kwargs={"autocommit": True}, open=True)


def three_writes(pool):
    results = []
    for _ in range(3):
        start = time.perf_counter()
        try:
            db.log_prediction(pool, BLANK, 434348, "probe", None)
            outcome = "ok"
        except Exception as err:
            outcome = type(err).__name__
        results.append(f"{outcome} {(time.perf_counter() - start) * 1000:.0f} ms")
    return results


checked, plain = db.connect(URL), unchecked(URL)
for pool in (checked, plain):
    three_writes(pool)
subprocess.run(["docker", "compose", "restart", "db"], capture_output=True)
time.sleep(3)
print("checked:", three_writes(checked))
print("plain:  ", three_writes(plain))
with checked.connection() as conn:
    conn.execute("DELETE FROM predictions WHERE model_version = 'probe'")
checked.close()
plain.close()
# checked: the first write waited about a second and succeeded. plain:
# the first write got the dead connection and failed, and the pool's
# warning between the lines is it discarding that connection.

DATABASE_URL=postgresql://listings:listings@localhost:5432/listings uv run python ../listings-probes/pool_check.py

checked: ['ok 1044 ms', 'ok 4 ms', 'ok 3 ms']
discarding closed connection: <psycopg.Connection [BAD] at 0x724297502240>
plain:   ['AdminShutdown 1 ms', 'ok 9 ms', 'ok 3 ms']

Theory Assessment

Q1: Three Calls, Three Lines

With logs.py as written, a teammate adds three calls to a route: logger.info("cache miss", extra={"fields": {"key": "Riverside"}}), logger.info("cache miss", extra={"key": "Riverside"}) and logger.info("cache miss", extra={"args": "Riverside"}). Say what each prints, and why logs.py collects an event's fields under one name.

Hint: Read which record attribute the formatter copies, and which attributes every record already carries.

Q2: The 500 That Was Never Logged

A teammate simplifies the middleware to response = await call_next(request), then the latency, the count and the log line, then return response, with no try. Say what the log, the count and /health show for a request whose route raises, and what the line status = 500 does in the version the lesson uses.

Hint: Follow what happens to the lines after call_next when call_next raises.

Q3: Account for Every Count

The service starts locally, with no Docker around it. In order, a client sends the reference listing, the {"rooms": 0} request, GET /health, GET /nope, DELETE /predict, and GET /health again. Give both /health replies' requests, rejected and errors, and say how the same sequence reads when the service runs in the compose stack instead.

Hint: A request is counted in the middleware's finally. Ask which statuses each field counts, and who else calls /health in the stack.

Q4: A Dashboard Built From the Table

A teammate builds the service's dashboard from the predictions table alone: rows per minute and the 95th percentile of latency_ms. Say what the dashboard shows during the single-connection break of the last subtitle, and during the first request after a restart with the pool, and name the signals that do show each event.

Hint: Ask what a failed request writes to the table, and what span of time the table's latency_ms covers.

Assignment

Assignment: Ready Is Not the Same as Alive

/health said ok through the whole break. Whether the service can serve a prediction right now is asked at a readiness check, an endpoint that answers 200 when everything a prediction needs responds and 503, Service Unavailable, when something does not. Write ~/dev/listings-probes/ready.py, a trial kept outside the project, that imports app and logger from listings.app and adds GET /ready to that app: it borrows a connection from app.state.db, runs SELECT 1, and answers {"ready": true, "database": "ok"}, or {"ready": false, "database": "unreachable"} with status 503 when no connection comes within two seconds, logging a not ready warning with the reason.

Three things the lesson did not use. pool.connection(timeout=2) gives up after two seconds instead of the pool's default thirty and raises PoolTimeout, from psycopg_pool. JSONResponse(content, status_code=503), from fastapi.responses, returns a body with the status you choose, where a returned dictionary is always 200. And uv run uvicorn --app-dir ../listings-probes ready:app serves a module outside the project, --app-dir adding that folder to the places Python imports from.

Stop the stack's API with docker compose stop api, keeping the database up, and serve the trial in Terminal 1 with DATABASE_URL pointing at the stack's database. In Terminal 2, printing each status and time with curl -w, call /ready, stop the database with docker compose stop db, call /ready, send the blank listing to /predict, call /health, then docker compose start db and call /ready once a second until it answers 200. Say in a comment what each answer shows, why /predict took as long as it did, and why the compose healthcheck should keep calling /health.

Hints:

• A route added to the imported app after /health is served like the others, and the middleware logs it, so its 503 lands in errors too.
• curl -s -w ' %{http_code} %{time_total}s\n' prints the status and the seconds after the body.

from fastapi import Request
from fastapi.responses import JSONResponse
from psycopg_pool import PoolTimeout

from listings.app import app, logger


@app.get("/ready")
def ready(request: Request):
    try:
        with request.app.state.db.connection(timeout=2) as conn:
            conn.execute("SELECT 1")
    except PoolTimeout as err:
        logger.warning("not ready", extra={"fields": {"reason": str(err)}})
        return JSONResponse({"ready": False, "database": "unreachable"}, status_code=503)
    return {"ready": True, "database": "ok"}
# Ready, then 503 in 2 s while the database is down, and ready again some
# seconds after it returns, with no restart. /predict waited the pool's
# default 30 s. The healthcheck stays on /health: restarting the API
# cannot bring a stopped database back.

docker compose stop api
DATABASE_URL=postgresql://listings:listings@localhost:5432/listings uv run uvicorn --app-dir ../listings-probes ready:app --no-access-log

T=' %{http_code} %{time_total}s\n'
curl -s -w "$T" http://127.0.0.1:8000/ready
docker compose stop db
curl -s -w "$T" http://127.0.0.1:8000/ready
curl -s -w "$T" -X POST http://127.0.0.1:8000/predict -H "Content-Type: application/json" -d '{"distance_km": 3.0, "rooms": 3, "bathrooms": 1, "neighborhood": "Riverside", "property_type": "apartment", "condition": "good"}'
curl -s -w "$T" http://127.0.0.1:8000/health

{"ready":true,"database":"ok"} 200 0.015110s
 Container listings-service-db-1 Stopping 
 Container listings-service-db-1 Stopped 
{"ready":false,"database":"unreachable"} 503 2.003533s
Internal Server Error 500 30.060309s
{"status":"ok","model_version":"3","uptime_s":33,"requests":3,"rejected":0,"errors":2} 200 0.001923s

error connecting in 'pool-1': connection failed: connection to server at "127.0.0.1", port 5432 failed: Connection refused
{"time": "2026-11-03T15:27:39", "level": "WARNING", "event": "not ready", "reason": "couldn't get a connection after 2.00 sec"}
psycopg_pool.PoolTimeout: couldn't get a connection after 30.00 sec

docker compose start db
for i in $(seq 1 40); do c=$(curl -s -o /dev/null -w '%{http_code}' http://127.0.0.1:8000/ready); echo "$(date +%T) $c"; [ $c = 200 ] && break; sleep 1; done

 Container listings-service-db-1 Starting 
 Container listings-service-db-1 Started 
15:28:51 503
15:28:54 503
15:28:57 503
15:28:58 200

Additional Resources

Optional, and nothing later in the module depends on them.

• Google SRE book, Chapter 6 - "Monitoring Distributed Systems", The Four Golden Signals. Latency, traffic, errors and saturation, the four numbers to watch on a user-facing service.
• PostgreSQL 18 documentation - "Aggregate Functions", Ordered-Set Aggregate Functions. percentile_cont, which interpolates, beside percentile_disc, which returns a value from the data, mode, and the array forms that compute several percentiles in one pass.

Summary

None of this lesson touched the model. The pipeline prices the reference listing at 384235, Lesson 3.2.3's price, and everything added sits around it: a line per request, a count per status, two columns per stored prediction and a pool under the database writes. That is what operating a model mostly is. The model's mistakes come later and quietly, and the next lesson measures them. What fails first is the machinery that carries requests to it and records what it said.

A database restart left a service that answered ok, that Docker called healthy, and whose table showed nothing worse than a quiet afternoon, while it failed every client who asked for a price. Each reading was true of what it measured: /health measured the process, Docker measured /health, and the table measured successes. Only the record of every request, written whether it succeeded or not and counted where nothing can skip it, measured what clients actually got, and the stored listings, each tagged with the version that priced them, are what the next lesson's drift is measured on.

Cheat Sheet

Part A - Reference Table

Part B - Compact Code Block

@app.middleware("http")
async def log_request(request, call_next):
    start = time.perf_counter()
    status = 500  # kept if the route raises
    try:
        response = await call_next(request)
        status = response.status_code
        return response
    finally:      # runs on success and on raise
        latency_ms = round((time.perf_counter() - start) * 1000, 2)
        request.app.state.counts[status] += 1
        logger.info("request", extra={"fields": {
            "method": request.method, "path": request.url.path,
            "status": status, "latency_ms": latency_ms,
        }})

pool = ConnectionPool(
    url, min_size=1, max_size=4,
    kwargs={"autocommit": True},
    check=ConnectionPool.check_connection,  # test before lending
    open=True,
)
with pool.connection() as conn:             # borrowed, then returned
    conn.execute("SELECT 1")